Skip to content

Neater logging #687

New issue

Have a question about this project? # for a free GitHub account to open an issue and contact its maintainers and the community.

#

By clicking “#”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? # to your account

Draft
wants to merge 2 commits into
base: main
Choose a base branch
from
Draft

Neater logging #687

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
237bc87
patch1
hiroshihorie Apr 29, 2025
793dacd
Remove set(trackState:)
hiroshihorie May 1, 2025
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
49 changes: 38 additions & 11 deletions Sources/LiveKit/Core/Room.swift
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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)
}

Expand Down Expand Up @@ -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)
Expand Down Expand Up @@ -307,7 +314,7 @@ public class Room: NSObject, @unchecked Sendable, ObservableObject, Loggable {
}

deinit {
log(nil, .trace)
log("Room instance deallocating", .trace)
}

@objc
Expand All @@ -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()

Expand Down Expand Up @@ -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
Expand All @@ -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()
Expand All @@ -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()
Expand Down Expand Up @@ -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)
Expand Down
106 changes: 75 additions & 31 deletions Sources/LiveKit/Core/SignalClient.swift
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -64,15 +64,20 @@
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")
}

let webSocket = try await self.requireWebSocket()
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,
])
}
})

Expand All @@ -99,19 +104,19 @@
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
Expand All @@ -124,9 +129,12 @@
{
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,
Expand All @@ -135,24 +143,26 @@
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) }

do {
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)
}
}
Expand Down Expand Up @@ -192,16 +202,23 @@
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()
Expand Down Expand Up @@ -234,7 +251,9 @@
// 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")
}

Expand All @@ -244,14 +263,16 @@
func _onWebSocketMessage(message: URLSessionWebSocketTask.Message) async {
let response: Livekit_SignalResponse? = {
switch message {
case let .data(data): return try? Livekit_SignalResponse(serializedData: data)

Check warning on line 266 in Sources/LiveKit/Core/SignalClient.swift

View workflow job for this annotation

GitHub Actions / Build & Test (macos-14, 15.4, iOS Simulator,OS=17.5,name=iPhone 15 Pro) 

'init(serializedData:extensions:partial:options:)' is deprecated: replaced by 'init(serializedBytes:extensions:partial:options:)'

Check warning on line 266 in Sources/LiveKit/Core/SignalClient.swift

View workflow job for this annotation

GitHub Actions / Build & Test (macos-14, 15.4, macOS) 

'init(serializedData:extensions:partial:options:)' is deprecated: replaced by 'init(serializedBytes:extensions:partial:options:)'

Check warning on line 266 in Sources/LiveKit/Core/SignalClient.swift

View workflow job for this annotation

GitHub Actions / Build & Test (macos-14, 15.4, macOS,variant=Mac Catalyst) 

'init(serializedData:extensions:partial:options:)' is deprecated: replaced by 'init(serializedBytes:extensions:partial:options:)'

Check warning on line 266 in Sources/LiveKit/Core/SignalClient.swift

View workflow job for this annotation

GitHub Actions / Build & Test (macos-14, 15.4, tvOS Simulator,name=Apple TV) 

'init(serializedData:extensions:partial:options:)' is deprecated: replaced by 'init(serializedBytes:extensions:partial:options:)'

Check warning on line 266 in Sources/LiveKit/Core/SignalClient.swift

View workflow job for this annotation

GitHub Actions / Build & Test (macos-15, 16.2, macOS, true) 

'init(serializedData:extensions:partial:options:)' is deprecated: replaced by 'init(serializedBytes:extensions:partial:options:)'

Check warning on line 266 in Sources/LiveKit/Core/SignalClient.swift

View workflow job for this annotation

GitHub Actions / Build & Test (macos-14, 15.4, visionOS Simulator,name=Apple Vision Pro) 

'init(serializedData:extensions:partial:options:)' is deprecated: replaced by 'init(serializedBytes:extensions:partial:options:)'

Check warning on line 266 in Sources/LiveKit/Core/SignalClient.swift

View workflow job for this annotation

GitHub Actions / Build & Test (macos-15, 16.2, iOS Simulator,OS=18.1,name=iPhone 16 Pro, true) 

'init(serializedData:extensions:partial:options:)' is deprecated: replaced by 'init(serializedBytes:extensions:partial:options:)'
case let .string(string): return try? Livekit_SignalResponse(jsonString: string)
default: return nil
}
}()

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
}

Expand All @@ -269,12 +290,16 @@

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
}

Expand Down Expand Up @@ -310,7 +335,10 @@
_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)

Expand Down Expand Up @@ -350,10 +378,10 @@
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)) }
Expand Down Expand Up @@ -613,7 +641,10 @@
}

// 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)
Expand All @@ -626,21 +657,26 @@
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))
}

_pingTimeoutTimer.restart()
}

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()
}
Expand All @@ -649,7 +685,10 @@
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()
}
Expand All @@ -665,7 +704,10 @@
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))
Expand All @@ -689,7 +731,9 @@
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")
}

Expand Down
Loading
Loading