Skip to content
New issue

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

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

Already on GitHub? Sign in to your account

fix: Correct module determination when logging #862

Open
wants to merge 2 commits into
base: main
Choose a base branch
from
Open
Show file tree
Hide file tree
Changes from all commits
Commits
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
7 changes: 6 additions & 1 deletion Package.swift
Original file line number Diff line number Diff line change
Expand Up @@ -227,7 +227,12 @@ let package = Package(
),
.testTarget(
name: "ClientRuntimeTests",
dependencies: ["ClientRuntime", "SmithyTestUtil", "SmithyStreams"],
dependencies: [
"ClientRuntime",
"SmithyTestUtil",
"SmithyStreams",
.product(name: "Logging", package: "swift-log"),
],
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

New logging test requires direct use of swift-log components, hence the test target dependency on swift-log

resources: [ .process("Resources") ]
),
.testTarget(
Expand Down
63 changes: 35 additions & 28 deletions Sources/Smithy/Logging/LogAgent.swift
Original file line number Diff line number Diff line change
@@ -1,14 +1,16 @@
/*
* Copyright Amazon.com, Inc. or its affiliates. All Rights Reserved.
* SPDX-License-Identifier: Apache-2.0.
*/
//
// Copyright Amazon.com Inc. or its affiliates.
// All Rights Reserved.
//
// SPDX-License-Identifier: Apache-2.0
//

public protocol LogAgent {
/// name of the struct or class where the logger was instantiated from
var name: String {get}
var name: String { get }

/// Get or set the configured log level.
var level: LogAgentLevel {get set}
var level: LogAgentLevel { get set }

/// This method is called when a `LogAgent` must emit a log message.
///
Expand Down Expand Up @@ -39,80 +41,85 @@ public enum LogAgentLevel: String, Codable, CaseIterable {
}

public extension LogAgent {
internal static func currentModule(filePath: String = #file) -> String {
let utf8All = filePath.utf8
return filePath.utf8.lastIndex(of: UInt8(ascii: "/")).flatMap { lastSlash -> Substring? in
utf8All[..<lastSlash].lastIndex(of: UInt8(ascii: "/")).map { secondLastSlash -> Substring in
filePath[utf8All.index(after: secondLastSlash) ..< lastSlash]
}
}.map {
String($0)
} ?? "n/a"
}

/// Log a message passing with the `.info` log level.
func info(_ message: String, file: String = #file, function: String = #function, line: UInt = #line) {
func info(_ message: String, file: String = #fileID, function: String = #function, line: UInt = #line) {
self.log(level: .info,
message: message,
metadata: nil,
source: Self.currentModule(),
source: currentModule(fileID: file),
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

All these log-level-specific functions are changed similarly. We weren't passing the caller's source file into the function that parses the module, hence every time we logged, it showed that it originated from the logger's module, not the caller's.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Also, #fileID is the proper path to use in modern Swift production code, not #file.

#fileID omits path components from the host machine, and makes the module easier to parse.

See https://www.swift.org/documentation/api-design-guidelines/#parameter-names .

file: file,
function: function,
line: line)
}

/// Log a message passing with the `LogLevel.warn` log level.
func warn(_ message: String, file: String = #file, function: String = #function, line: UInt = #line) {
func warn(_ message: String, file: String = #fileID, function: String = #function, line: UInt = #line) {
self.log(level: .warn,
message: message,
metadata: nil,
source: Self.currentModule(),
source: currentModule(fileID: file),
file: file,
function: function,
line: line)
}

/// Log a message passing with the `.debug` log level.
func debug(_ message: String, file: String = #file, function: String = #function, line: UInt = #line) {
func debug(_ message: String, file: String = #fileID, function: String = #function, line: UInt = #line) {
self.log(level: .debug,
message: message,
metadata: nil,
source: Self.currentModule(),
source: currentModule(fileID: file),
file: file,
function: function,
line: line)
}

/// Log a message passing with the `.error` log level.
func error(_ message: String, file: String = #file, function: String = #function, line: UInt = #line) {
func error(_ message: String, file: String = #fileID, function: String = #function, line: UInt = #line) {
self.log(level: .error,
message: message,
metadata: nil,
source: Self.currentModule(),
source: currentModule(fileID: file),
file: file,
function: function,
line: line)
}

/// Log a message passing with the `.trace` log level.
func trace(_ message: String, file: String = #file, function: String = #function, line: UInt = #line) {
func trace(_ message: String, file: String = #fileID, function: String = #function, line: UInt = #line) {
self.log(level: .trace,
message: message,
metadata: nil,
source: Self.currentModule(),
source: currentModule(fileID: file),
file: file,
function: function,
line: line)
}

/// Log a message passing with the `.fatal` log level.
func fatal(_ message: String, file: String = #file, function: String = #function, line: UInt = #line) {
func fatal(_ message: String, file: String = #fileID, function: String = #function, line: UInt = #line) {
self.log(level: .fatal,
message: message,
metadata: nil,
source: Self.currentModule(),
source: currentModule(fileID: file),
file: file,
function: function,
line: line)
}
}

/// Parses the module name from `#fileID`.
///
/// Instructions for parsing module from `#fileID` are here:
/// https://developer.apple.com/documentation/swift/fileid()
/// - Parameter fileID: The value of the `#fileID` macro at the point of logging.
/// - Returns: The name of the module, as parsed from the passed `#fileID`.
private func currentModule(fileID: String) -> String {
let utf8All = fileID.utf8
if let slashIndex = utf8All.firstIndex(of: UInt8(ascii: "/")) {
return String(fileID[..<slashIndex])
} else {
return "n/a"
}
}
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Compare this currentModule() function to the one deleted above; this one is significantly simpler because #fileID always has the module name right out front, followed by a /.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Also I should point out this is exactly how swift-log makes this determination for itself:
https://github.com/apple/swift-log/blob/main/Sources/Logging/Logging.swift#L1523

7 changes: 7 additions & 0 deletions Sources/Smithy/Logging/SwiftLog+LogAgent.swift
Original file line number Diff line number Diff line change
Expand Up @@ -22,6 +22,13 @@ public struct SwiftLogger: LogAgent {
self.logLevel = logLevel
}

// This initializer is currently only used in tests, to inject a mock LogHandler.
init(label: String, logLevel: LogAgentLevel, factory: (String) -> any LogHandler) {
self.label = label
self.logLevel = logLevel
self.logger = Logger(label: label, factory: factory)
}

public var level: LogAgentLevel {
get {
return logLevel
Expand Down
133 changes: 133 additions & 0 deletions Tests/ClientRuntimeTests/LoggingTests/SwiftLoggerTests.swift
Original file line number Diff line number Diff line change
@@ -0,0 +1,133 @@
//
// Copyright Amazon.com Inc. or its affiliates.
// All Rights Reserved.
//
// SPDX-License-Identifier: Apache-2.0
//

import XCTest
@testable import Smithy
import ClientRuntime
import Logging

final class SwiftLoggerTests: XCTestCase {
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This test creates a SwiftLogger with a mock LogHandler injected (LogHandler is the entry point to swift-log; the mock is defined below the tests.)

A log statement is executed at every log level, and it is verified that the correct log params are received by the LogHandler.


func test_log_logsTraceLevelMessage() throws {
try logsLeveledMessage(logLevel: .trace, loggerBlock: { $0.trace })
}

func test_log_logsDebugLevelMessage() throws {
try logsLeveledMessage(logLevel: .debug, loggerBlock: { $0.debug })
}

func test_log_logsInfoLevelMessage() throws {
try logsLeveledMessage(logLevel: .info, loggerBlock: { $0.info })
}

func test_log_logsWarnLevelMessage() throws {
try logsLeveledMessage(logLevel: .warning, loggerBlock: { $0.warn })
}

func test_log_logsErrorLevelMessage() throws {
try logsLeveledMessage(logLevel: .error, loggerBlock: { $0.error })
}

func test_log_logsFatalLevelMessage() throws {
try logsLeveledMessage(logLevel: .critical, loggerBlock: { $0.fatal })
}

private func logsLeveledMessage(
logLevel: Logger.Level,
loggerBlock: (SwiftLogger) -> (String, String, String, UInt) -> Void,
testFile: StaticString = #filePath,
testLine: UInt = #line
) throws {
// Select randomized params for the test
let logMessage = UUID().uuidString
let module = UUID().uuidString
let fileName = UUID().uuidString
let fileID = "\(module)/\(fileName).swift"
let function = UUID().uuidString
let line = UInt.random(in: 0...UInt.max)

// Create a TestLogHandler, then create a SwiftLogger (the test subject)
// with it.
var logHandler: TestLogHandler!
let subject = SwiftLogger(label: "Test", logLevel: .trace, factory: { label in
logHandler = TestLogHandler(label: label)
return logHandler
})

// Invoke the logger, then get the TestLogInvocation with the params sent into
// swift-log.
loggerBlock(subject)(logMessage, fileID, function, line)
let invocation = try XCTUnwrap(logHandler.invocations.first)

// Verify the assertions on each param submitted into swift-log.
XCTAssertEqual(invocation.level, logLevel, file: testFile, line: testLine)
XCTAssertEqual(invocation.message, Logger.Message(stringLiteral: logMessage), file: testFile, line: testLine)
XCTAssertEqual(invocation.source, module, file: testFile, line: testLine)
XCTAssertEqual(invocation.file, fileID, file: testFile, line: testLine)
XCTAssertEqual(invocation.function, function, file: testFile, line: testLine)
XCTAssertEqual(invocation.line, line, file: testFile, line: testLine)
}
}


private class TestLogHandler: LogHandler {
let label: String
var invocations = [TestLogInvocation]()

init(label: String) {
self.label = label
}

subscript(metadataKey metadataKey: String) -> Logging.Logger.Metadata.Value? {
get {
metadata[metadataKey]
}
set {
if let newValue {
metadata.updateValue(newValue, forKey: metadataKey)
} else {
metadata.removeValue(forKey: metadataKey)
}
}
}

var metadata: Logging.Logger.Metadata = Logging.Logger.Metadata()

var logLevel: Logging.Logger.Level = .trace

func log(
level: Logger.Level,
message: Logger.Message,
metadata: Logger.Metadata?,
source: String,
file: String,
function: String,
line: UInt
) {
invocations.append(
TestLogInvocation(
level: level,
message: message,
metadata: metadata,
source: source,
file: file,
function: function,
line: line
)
)
}
}

private struct TestLogInvocation {
let level: Logger.Level
let message: Logger.Message
let metadata: Logger.Metadata?
let source: String
let file: String
let function: String
let line: UInt
}
Original file line number Diff line number Diff line change
Expand Up @@ -104,7 +104,7 @@ class FoundationStreamBridgeTests: XCTestCase {
}
}

class TestLogger: LogAgent {
private class TestLogger: LogAgent {
var name: String

var messages: [(level: LogAgentLevel, message: String)] = []
Expand Down
Loading