Implement logging

The aim of this commit is to:

- provide infrastructure for internal components to be able to log
  messages
- add some log messages to the existing functionality (I am not
  particularly concerned by the quality or utility of these log messages
  at the moment)
- provide a basic default logging backend so that users can see log
  messages in the console

The choice to have a separate internal logging interface is taken from
Asset Tracking and ably-cocoa, where I think it works well. I haven’t
currently copied across Asset Tracking’s subsystem mechanism, a large
part of the motivation for which was to provide a way to integrate the
logs emitted by the AAT-instantiated Realtime client into those emitted
by AAT itself; this is not currently a goal for Chat, which does not
instantiate a Realtime client.

I briefly toyed with the idea of writing a macro that would log the
inputs and outputs of public API methods, but figuring out how to do
that didn’t seem like a good use of time now.

Resolves #38.

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 {

Sources/AblyChat/Logging.swift

@@ -1,14 +1,92 @@
+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
     case warn
     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
+        }
+    }
+}

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)
     }

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<RoomStatusChange>] = []
 
@@ -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 {

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
         }

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)
+    }
+}

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
 

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?

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()

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.
+    }
+}

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<T> {
+    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))
+    }
+}