From 4b72ffccade595e55790938f88f047800d0fcfff Mon Sep 17 00:00:00 2001 From: Lawrence Forooghian Date: Tue, 3 Sep 2024 15:17:09 +0100 Subject: [PATCH] Implement logging MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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 (AAT) and ably-cocoa, where I think it works well. I haven’t currently copied across AAT’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 | 4 +- Sources/AblyChat/Logging.swift | 81 ++++++++++++++++++- Sources/AblyChat/Room.swift | 21 ++++- Sources/AblyChat/RoomStatus.swift | 7 ++ Sources/AblyChat/Rooms.swift | 7 +- .../DefaultInternalLoggerTests.swift | 49 +++++++++++ .../DefaultRoomStatusTests.swift | 6 +- Tests/AblyChatTests/DefaultRoomTests.swift | 8 +- Tests/AblyChatTests/DefaultRoomsTests.swift | 6 +- .../Helpers/SynchronizedAccess.swift | 30 +++++++ Tests/AblyChatTests/Helpers/TestLogger.swift | 7 ++ Tests/AblyChatTests/InternalLoggerTests.swift | 17 ++++ .../Mocks/MockInternalLogger.swift | 9 +++ .../AblyChatTests/Mocks/MockLogHandler.swift | 9 +++ 14 files changed, 243 insertions(+), 18 deletions(-) create mode 100644 Tests/AblyChatTests/DefaultInternalLoggerTests.swift create mode 100644 Tests/AblyChatTests/Helpers/SynchronizedAccess.swift create mode 100644 Tests/AblyChatTests/Helpers/TestLogger.swift create mode 100644 Tests/AblyChatTests/InternalLoggerTests.swift create mode 100644 Tests/AblyChatTests/Mocks/MockInternalLogger.swift create mode 100644 Tests/AblyChatTests/Mocks/MockLogHandler.swift diff --git a/Sources/AblyChat/ChatClient.swift b/Sources/AblyChat/ChatClient.swift index 1ad57e5..917a22f 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 307c26a..4a651e1 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,80 @@ 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 ?? .error + } + + 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 + } + + // TODO: revisit in Xcode 16, where Logger is Sendable (https://github.com/ably-labs/ably-chat-swift/issues/40) + 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 c7ef5db..e720931 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 87a3978..b26c1f4 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 03b32d9..12fd6ef 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 0000000..07df9ac --- /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) + + XCTAssertTrue(logger.logHandler is DefaultLogHandler) + XCTAssertEqual(logger.logLevel, .error) + } + + 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 75f58da..ec5d2cb 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 7f600ba..d886dae 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 31fc83d..48ec802 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/SynchronizedAccess.swift b/Tests/AblyChatTests/Helpers/SynchronizedAccess.swift new file mode 100644 index 0000000..a5888b3 --- /dev/null +++ b/Tests/AblyChatTests/Helpers/SynchronizedAccess.swift @@ -0,0 +1,30 @@ +import Foundation + +/// 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 + } +} diff --git a/Tests/AblyChatTests/Helpers/TestLogger.swift b/Tests/AblyChatTests/Helpers/TestLogger.swift new file mode 100644 index 0000000..265ec22 --- /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 0000000..3c91dd3 --- /dev/null +++ b/Tests/AblyChatTests/InternalLoggerTests.swift @@ -0,0 +1,17 @@ +@testable import AblyChat +import XCTest + +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 0000000..11cac6b --- /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 0000000..2678cfb --- /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) + } +}