diff --git a/Sources/AblyChat/ChatClient.swift b/Sources/AblyChat/ChatClient.swift index 1ad57e5a..917a22f1 100644 --- a/Sources/AblyChat/ChatClient.swift +++ b/Sources/AblyChat/ChatClient.swift @@ -14,11 +14,13 @@ public actor DefaultChatClient: ChatClient { public let realtime: RealtimeClient public nonisolated let clientOptions: ClientOptions public nonisolated let rooms: Rooms + private let logger: InternalLogger public init(realtime: RealtimeClient, clientOptions: ClientOptions?) { self.realtime = realtime self.clientOptions = clientOptions ?? .init() - rooms = DefaultRooms(realtime: realtime, clientOptions: self.clientOptions) + logger = DefaultInternalLogger(logHandler: self.clientOptions.logHandler, logLevel: self.clientOptions.logLevel) + rooms = DefaultRooms(realtime: realtime, clientOptions: self.clientOptions, logger: logger) } public nonisolated var connection: any Connection { diff --git a/Sources/AblyChat/Logging.swift b/Sources/AblyChat/Logging.swift index 307c26a4..9dbbf80d 100644 --- a/Sources/AblyChat/Logging.swift +++ b/Sources/AblyChat/Logging.swift @@ -1,10 +1,12 @@ +import os + public typealias LogContext = [String: any Sendable] public protocol LogHandler: AnyObject, Sendable { func log(message: String, level: LogLevel, context: LogContext?) } -public enum LogLevel: Sendable { +public enum LogLevel: Sendable, Comparable { case trace case debug case info @@ -12,3 +14,79 @@ public enum LogLevel: Sendable { case error case silent } + +/// A reference to a line within a source code file. +internal struct CodeLocation: Equatable { + /// A file identifier in the format used by Swift’s `#fileID` macro. For example, `"AblyChat/Room.swift"`. + internal var fileID: String + /// The line number in the source code file referred to by ``fileID``. + internal var line: Int +} + +/// A log handler to be used by components of the Chat SDK. +/// +/// This protocol exists to give internal SDK components access to a logging interface that allows them to provide rich and granular logging information, whilst giving us control over how much of this granularity we choose to expose to users of the SDK versus instead handling it for them by, say, interpolating it into a log message. It also allows us to evolve the logging interface used internally without introducing breaking changes for users of the SDK. +internal protocol InternalLogger: Sendable { + /// Logs a message. + /// - Parameters: + /// - message: The message to log. + /// - level: The log level of the message. + /// - codeLocation: The location in the code where the message was emitted. + func log(message: String, level: LogLevel, codeLocation: CodeLocation) +} + +extension InternalLogger { + /// A convenience logging method that uses the call site’s #file and #line values. + public func log(message: String, level: LogLevel, fileID: String = #fileID, line: Int = #line) { + let codeLocation = CodeLocation(fileID: fileID, line: line) + log(message: message, level: level, codeLocation: codeLocation) + } +} + +internal final class DefaultInternalLogger: InternalLogger { + // Exposed for testing. + internal let logHandler: LogHandler + internal let logLevel: LogLevel + + internal init(logHandler: LogHandler?, logLevel: LogLevel?) { + self.logHandler = logHandler ?? DefaultLogHandler() + self.logLevel = logLevel ?? .info + } + + internal func log(message: String, level: LogLevel, codeLocation: CodeLocation) { + guard level >= logLevel else { + return + } + + // I don’t yet know what `context` is for (will figure out in https://github.com/ably-labs/ably-chat-swift/issues/8) so passing nil for now + logHandler.log(message: "(\(codeLocation.fileID):\(codeLocation.line)) \(message)", level: level, context: nil) + } +} + +/// The logging backend used by ``DefaultInternalLogHandler`` if the user has not provided their own. Uses Swift’s `Logger` type for logging. +internal final class DefaultLogHandler: LogHandler { + internal func log(message: String, level: LogLevel, context _: LogContext?) { + guard let osLogType = level.toOSLogType else { + // Treating .silent as meaning "don’t log it", will figure out the meaning of .silent in https://github.com/ably-labs/ably-chat-swift/issues/8 + return + } + + let logger = Logger() + logger.log(level: osLogType, "\(message)") + } +} + +private extension LogLevel { + var toOSLogType: OSLogType? { + switch self { + case .debug, .trace: + .debug + case .info: + .info + case .warn, .error: + .error + case .silent: + nil + } + } +} diff --git a/Sources/AblyChat/Room.swift b/Sources/AblyChat/Room.swift index c7ef5db9..e7209319 100644 --- a/Sources/AblyChat/Room.swift +++ b/Sources/AblyChat/Room.swift @@ -24,12 +24,15 @@ internal actor DefaultRoom: Room { // Exposed for testing. internal nonisolated let realtime: RealtimeClient - private let _status = DefaultRoomStatus() + private let _status: DefaultRoomStatus + private let logger: InternalLogger - internal init(realtime: RealtimeClient, roomID: String, options: RoomOptions) { + internal init(realtime: RealtimeClient, roomID: String, options: RoomOptions, logger: InternalLogger) { self.realtime = realtime self.roomID = roomID self.options = options + self.logger = logger + _status = .init(logger: logger) } public nonisolated var messages: any Messages { @@ -69,14 +72,24 @@ internal actor DefaultRoom: Room { public func attach() async throws { for channel in channels() { - try await channel.attachAsync() + do { + try await channel.attachAsync() + } catch { + logger.log(message: "Failed to attach channel \(channel), error \(error)", level: .error) + throw error + } } await _status.transition(to: .attached) } public func detach() async throws { for channel in channels() { - try await channel.detachAsync() + do { + try await channel.detachAsync() + } catch { + logger.log(message: "Failed to detach channel \(channel), error \(error)", level: .error) + throw error + } } await _status.transition(to: .detached) } diff --git a/Sources/AblyChat/RoomStatus.swift b/Sources/AblyChat/RoomStatus.swift index 87a39783..b26c1f48 100644 --- a/Sources/AblyChat/RoomStatus.swift +++ b/Sources/AblyChat/RoomStatus.swift @@ -37,6 +37,12 @@ internal actor DefaultRoomStatus: RoomStatus { // TODO: populate this (https://github.com/ably-labs/ably-chat-swift/issues/28) internal private(set) var error: ARTErrorInfo? + private let logger: InternalLogger + + internal init(logger: InternalLogger) { + self.logger = logger + } + // TODO: clean up old subscriptions (https://github.com/ably-labs/ably-chat-swift/issues/36) private var subscriptions: [Subscription] = [] @@ -48,6 +54,7 @@ internal actor DefaultRoomStatus: RoomStatus { /// Sets ``current`` to the given state, and emits a status change to all subscribers added via ``onChange(bufferingPolicy:)``. internal func transition(to newState: RoomLifecycle) { + logger.log(message: "Transitioning to \(newState)", level: .debug) let statusChange = RoomStatusChange(current: newState, previous: current) current = newState for subscription in subscriptions { diff --git a/Sources/AblyChat/Rooms.swift b/Sources/AblyChat/Rooms.swift index 03b32d9f..12fd6ef1 100644 --- a/Sources/AblyChat/Rooms.swift +++ b/Sources/AblyChat/Rooms.swift @@ -11,12 +11,15 @@ internal actor DefaultRooms: Rooms { internal nonisolated let realtime: RealtimeClient internal nonisolated let clientOptions: ClientOptions + private let logger: InternalLogger + /// The set of rooms, keyed by room ID. private var rooms: [String: DefaultRoom] = [:] - internal init(realtime: RealtimeClient, clientOptions: ClientOptions) { + internal init(realtime: RealtimeClient, clientOptions: ClientOptions, logger: InternalLogger) { self.realtime = realtime self.clientOptions = clientOptions + self.logger = logger } internal func get(roomID: String, options: RoomOptions) throws -> any Room { @@ -30,7 +33,7 @@ internal actor DefaultRooms: Rooms { return existingRoom } else { - let room = DefaultRoom(realtime: realtime, roomID: roomID, options: options) + let room = DefaultRoom(realtime: realtime, roomID: roomID, options: options, logger: logger) rooms[roomID] = room return room } diff --git a/Tests/AblyChatTests/DefaultInternalLoggerTests.swift b/Tests/AblyChatTests/DefaultInternalLoggerTests.swift new file mode 100644 index 00000000..02f9ea90 --- /dev/null +++ b/Tests/AblyChatTests/DefaultInternalLoggerTests.swift @@ -0,0 +1,49 @@ +@testable import AblyChat +import XCTest + +class DefaultInternalLoggerTests: XCTestCase { + func test_defaults() { + let logger = DefaultInternalLogger(logHandler: nil, logLevel: nil) + + XCTAssertIdentical(type(of: logger.logHandler), DefaultLogHandler.self) + XCTAssertEqual(logger.logLevel, .info) + } + + func test_log() throws { + // Given: A DefaultInternalLogger instance + let logHandler = MockLogHandler() + let logger = DefaultInternalLogger(logHandler: logHandler, logLevel: nil) + + // When: `log(message:level:codeLocation:)` is called on it + logger.log( + message: "Hello", + level: .error, // arbitrary + codeLocation: .init(fileID: "Ably/Room.swift", line: 123) + ) + + // Then: It calls log(…) on the underlying logger, interpolating the code location into the message and passing through the level + let logArguments = try XCTUnwrap(logHandler.logArguments) + XCTAssertEqual(logArguments.message, "(Ably/Room.swift:123) Hello") + XCTAssertEqual(logArguments.level, .error) + XCTAssertNil(logArguments.context) + } + + func test_log_whenLogLevelArgumentIsLessSevereThanLogLevelProperty_itDoesNotLog() { + // Given: A DefaultInternalLogger instance + let logHandler = MockLogHandler() + let logger = DefaultInternalLogger( + logHandler: logHandler, + logLevel: .info // arbitrary + ) + + // When: `log(message:level:codeLocation:)` is called on it, with `level` less severe than that of the instance + logger.log( + message: "Hello", + level: .debug, + codeLocation: .init(fileID: "", line: 0) + ) + + // Then: It does not call `log(…)` on the underlying logger + XCTAssertNil(logHandler.logArguments) + } +} diff --git a/Tests/AblyChatTests/DefaultRoomStatusTests.swift b/Tests/AblyChatTests/DefaultRoomStatusTests.swift index 75f58dad..ec5d2cb5 100644 --- a/Tests/AblyChatTests/DefaultRoomStatusTests.swift +++ b/Tests/AblyChatTests/DefaultRoomStatusTests.swift @@ -3,20 +3,20 @@ import XCTest class DefaultRoomStatusTests: XCTestCase { func test_current_startsAsInitialized() async { - let status = DefaultRoomStatus() + let status = DefaultRoomStatus(logger: TestLogger()) let current = await status.current XCTAssertEqual(current, .initialized) } func test_error_startsAsNil() async { - let status = DefaultRoomStatus() + let status = DefaultRoomStatus(logger: TestLogger()) let error = await status.error XCTAssertNil(error) } func test_transition() async { // Given: A RoomStatus - let status = DefaultRoomStatus() + let status = DefaultRoomStatus(logger: TestLogger()) let originalState = await status.current let newState = RoomLifecycle.attached // arbitrary diff --git a/Tests/AblyChatTests/DefaultRoomTests.swift b/Tests/AblyChatTests/DefaultRoomTests.swift index 7f600ba7..d886dae0 100644 --- a/Tests/AblyChatTests/DefaultRoomTests.swift +++ b/Tests/AblyChatTests/DefaultRoomTests.swift @@ -16,7 +16,7 @@ class DefaultRoomTests: XCTestCase { ] let channels = MockChannels(channels: channelsList) let realtime = MockRealtime.create(channels: channels) - let room = DefaultRoom(realtime: realtime, roomID: "basketball", options: .init()) + let room = DefaultRoom(realtime: realtime, roomID: "basketball", options: .init(), logger: TestLogger()) let subscription = await room.status.onChange(bufferingPolicy: .unbounded) async let attachedStatusChange = subscription.first { $0.current == .attached } @@ -53,7 +53,7 @@ class DefaultRoomTests: XCTestCase { ] let channels = MockChannels(channels: channelsList) let realtime = MockRealtime.create(channels: channels) - let room = DefaultRoom(realtime: realtime, roomID: "basketball", options: .init()) + let room = DefaultRoom(realtime: realtime, roomID: "basketball", options: .init(), logger: TestLogger()) // When: `attach` is called on the room let roomAttachError: Error? @@ -82,7 +82,7 @@ class DefaultRoomTests: XCTestCase { ] let channels = MockChannels(channels: channelsList) let realtime = MockRealtime.create(channels: channels) - let room = DefaultRoom(realtime: realtime, roomID: "basketball", options: .init()) + let room = DefaultRoom(realtime: realtime, roomID: "basketball", options: .init(), logger: TestLogger()) let subscription = await room.status.onChange(bufferingPolicy: .unbounded) async let detachedStatusChange = subscription.first { $0.current == .detached } @@ -119,7 +119,7 @@ class DefaultRoomTests: XCTestCase { ] let channels = MockChannels(channels: channelsList) let realtime = MockRealtime.create(channels: channels) - let room = DefaultRoom(realtime: realtime, roomID: "basketball", options: .init()) + let room = DefaultRoom(realtime: realtime, roomID: "basketball", options: .init(), logger: TestLogger()) // When: `detach` is called on the room let roomDetachError: Error? diff --git a/Tests/AblyChatTests/DefaultRoomsTests.swift b/Tests/AblyChatTests/DefaultRoomsTests.swift index 31fc83dd..48ec802b 100644 --- a/Tests/AblyChatTests/DefaultRoomsTests.swift +++ b/Tests/AblyChatTests/DefaultRoomsTests.swift @@ -6,7 +6,7 @@ class DefaultRoomsTests: XCTestCase { func test_get_returnsRoomWithGivenID() async throws { // Given: an instance of DefaultRooms let realtime = MockRealtime.create() - let rooms = DefaultRooms(realtime: realtime, clientOptions: .init()) + let rooms = DefaultRooms(realtime: realtime, clientOptions: .init(), logger: TestLogger()) // When: get(roomID:options:) is called let roomID = "basketball" @@ -24,7 +24,7 @@ class DefaultRoomsTests: XCTestCase { func test_get_returnsExistingRoomWithGivenID() async throws { // Given: an instance of DefaultRooms, on which get(roomID:options:) has already been called with a given ID let realtime = MockRealtime.create() - let rooms = DefaultRooms(realtime: realtime, clientOptions: .init()) + let rooms = DefaultRooms(realtime: realtime, clientOptions: .init(), logger: TestLogger()) let roomID = "basketball" let options = RoomOptions() @@ -41,7 +41,7 @@ class DefaultRoomsTests: XCTestCase { func test_get_throwsErrorWhenOptionsDoNotMatch() async throws { // Given: an instance of DefaultRooms, on which get(roomID:options:) has already been called with a given ID and options let realtime = MockRealtime.create() - let rooms = DefaultRooms(realtime: realtime, clientOptions: .init()) + let rooms = DefaultRooms(realtime: realtime, clientOptions: .init(), logger: TestLogger()) let roomID = "basketball" let options = RoomOptions() diff --git a/Tests/AblyChatTests/Helpers/TestLogger.swift b/Tests/AblyChatTests/Helpers/TestLogger.swift new file mode 100644 index 00000000..265ec22b --- /dev/null +++ b/Tests/AblyChatTests/Helpers/TestLogger.swift @@ -0,0 +1,7 @@ +@testable import AblyChat + +struct TestLogger: InternalLogger { + func log(message _: String, level _: LogLevel, codeLocation _: CodeLocation) { + // No-op; currently we don’t log in tests to keep the test logs easy to read. Can reconsider if necessary. + } +} diff --git a/Tests/AblyChatTests/InternalLoggerTests.swift b/Tests/AblyChatTests/InternalLoggerTests.swift new file mode 100644 index 00000000..f34d7056 --- /dev/null +++ b/Tests/AblyChatTests/InternalLoggerTests.swift @@ -0,0 +1,46 @@ +@testable import AblyChat +import XCTest + +/// A property wrapper that uses a mutex to protect its wrapped value from concurrent reads and writes. Similar to Objective-C’s `@atomic`. +/// +/// Don’t overestimate the abilities of this property wrapper; it won’t allow you to, for example, increment a counter in a threadsafe manner. +@propertyWrapper +struct SynchronizedAccess { + var wrappedValue: T { + get { + let value: T + mutex.lock() + value = _wrappedValue + mutex.unlock() + return value + } + + set { + mutex.lock() + _wrappedValue = newValue + mutex.unlock() + } + } + + private var _wrappedValue: T + private var mutex = NSLock() + + init(wrappedValue: T) { + _wrappedValue = wrappedValue + } +} + +class InternalLoggerTests: XCTestCase { + func test_protocolExtension_logMessage_defaultArguments_populatesFileIDAndLine() throws { + let logger = MockInternalLogger() + + let expectedLine = #line + 1 + logger.log(message: "Here is a message", level: .info) + + let receivedArguments = try XCTUnwrap(logger.logArguments) + + XCTAssertEqual(receivedArguments.level, .info) + XCTAssertEqual(receivedArguments.message, "Here is a message") + XCTAssertEqual(receivedArguments.codeLocation, .init(fileID: #fileID, line: expectedLine)) + } +} diff --git a/Tests/AblyChatTests/Mocks/MockInternalLogger.swift b/Tests/AblyChatTests/Mocks/MockInternalLogger.swift new file mode 100644 index 00000000..11cac6b7 --- /dev/null +++ b/Tests/AblyChatTests/Mocks/MockInternalLogger.swift @@ -0,0 +1,9 @@ +@testable import AblyChat + +final class MockInternalLogger: InternalLogger, @unchecked Sendable { + @SynchronizedAccess var logArguments: (message: String, level: LogLevel, codeLocation: CodeLocation)? + + func log(message: String, level: LogLevel, codeLocation: CodeLocation) { + logArguments = (message: message, level: level, codeLocation: codeLocation) + } +} diff --git a/Tests/AblyChatTests/Mocks/MockLogHandler.swift b/Tests/AblyChatTests/Mocks/MockLogHandler.swift new file mode 100644 index 00000000..2678cfbf --- /dev/null +++ b/Tests/AblyChatTests/Mocks/MockLogHandler.swift @@ -0,0 +1,9 @@ +import AblyChat + +final class MockLogHandler: LogHandler, @unchecked Sendable { + @SynchronizedAccess var logArguments: (message: String, level: LogLevel, context: LogContext?)? + + func log(message: String, level: LogLevel, context: LogContext?) { + logArguments = (message: message, level: level, context: context) + } +}