Skip to content

Commit

Permalink
Add locking when emitting messages
Browse files Browse the repository at this point in the history 
Add comments on public API

Use isSwiftLogging() so that mapping between loggers is not duplicated
  • Loading branch information
@djones6
djones6 committed May 23, 2019
1 parent f41262d commit 312c0c8
Showing 1 changed file with 74 additions and 14 deletions.
88 changes: 74 additions & 14 deletions Sources/LoggerAPI/Logger.swift
View file
Original file line number Diff line number Diff line change
Expand Up @@ -15,6 +15,7 @@
**/

import Logging
import Dispatch

/// Implement the `CustomStringConvertible` protocol for the `LoggerMessageType` enum
extension LoggerMessageType: CustomStringConvertible {
Expand Down Expand Up @@ -71,9 +72,18 @@ public class Log {

/// An instance of the logger. It should usually be the one and only reference
/// of the `Logger` protocol implementation in the system.
/// This can be used in addition to `swiftLogger`, in which case log messages
/// will be sent to both loggers.
public static var logger: Logger?

public static var swiftLogger: Logging.Logger? = Logging.Logger(label: "com.ibm.LoggerAPI.globalLogger")
/// An instance of a swift-log Logger. If set, LoggerAPI will direct log messages
/// to swift-log. This can be used in addition to `logger`, in which case log
/// messages will be sent to both loggers.
public static var swiftLogger: Logging.Logger? = nil

This comment has been minimized.

Sign in to view

Copy link
@weissi

weissi May 23, 2019

This is also unsafe, this is a public mutable property that isn’t locked. I would suggest making this a computed property and putting the locking there. The. All the accesses (ie the rest of the file) doesn’t need to worry about it. Does this make sense? Please ping if you have any Qs

// Locks to provide thread safety when writing to loggers
private static var logLock = pthread_rwlock_t()

This comment has been minimized.

Sign in to view

Copy link
@weissi

weissi May 23, 2019

this is not safe in Swift. When you take the address of this thing, the compiler is free to do the following:

let tmp = logLock // this COPIES the mutex, ie. it won't be a working mutex anymore
withUnsafeBytes(to: &tmp) { ptr in
    pthread_rwlock_wrlock(ptr)
}
logLock = tmp // copy it back

This comment has been minimized.

Sign in to view

Copy link
@weissi

weissi May 23, 2019

You should import Foundation and use their Lock

This comment has been minimized.

Sign in to view

Copy link
@djones6

djones6 May 23, 2019

Author Contributor

Oh wow.

I had also considered using DispatchQueue. I've implemented r/w locks before using a concurrent queue and the flags: .barrier facility, which I recall being substantially faster than Foundation's Lock, eg. In Kitura/Kitura-net#284

This comment has been minimized.

Sign in to view

Copy link
@weissi

weissi May 23, 2019

Well, most importantly, we should fix the correctness issue here.

DispatchQueues will do just fine as a regular or as a rw lock. However, using dispatch queues as a lock whilst really fast in (Obj)C is unfortunately quite slow in Swift (https://bugs.swift.org/browse/SR-4937). Note, this doesn’t apply to dispatch semaphores.

If I were you, I’d switch to Foundation.Lock. If you’re super worried about performance use NIOConcurrencyHelpers.Lock
private static var swiftLogLock = pthread_rwlock_t()

/// Log a message for use when in verbose logging mode.
///
Expand All @@ -90,11 +100,15 @@ public class Log {
public static func verbose(_ msg: @autoclosure () -> String, functionName: String = #function,
lineNum: Int = #line, fileName: String = #file ) {
if let logger = logger, logger.isLogging(.verbose) {
pthread_rwlock_wrlock(&logLock)

This comment has been minimized.

Sign in to view

Copy link
@weissi

weissi May 23, 2019

This critical section is placed wrongly. What you need to protect is the access to logger, what you have protected is the use of logger. This should be

if let logger = logLock.withLock({ logger }) {
    logger.log(...)
}

assuming you have the following code

extension Foundation.Lock {
    func withLock<T>(_ body: () throws -> T) rethrows -> T {
        self.lock()
        defer {
            self.unlock()
        }
        return try body()
    }
}

This comment has been minimized.

Sign in to view

Copy link
@weissi

weissi May 23, 2019

(also if you use a RW lock, this place would only need the read lock)

This comment has been minimized.

Sign in to view

Copy link
@djones6

djones6 May 23, 2019

Author Contributor

Oh wait, is this because the Logger itself can be mutated? I was only trying to prevent concurrent calls to log().

This comment has been minimized.

Sign in to view

Copy link
@weissi

weissi May 23, 2019

Logger is a value type when considering its mutating methods (log level/metadata changes) so no locks required to change that.

Regarding the logging methods (who aren’t mutating), you don’t need to lock those either, that’s the logging backend’s job. Imagine a world where the caller of the logging methods would need to lock, that’s totally unusable because every piece of code that wants to log would need to agree which lock to use.

So what you need to do here is to lock all acccesses to the property that holds the Logger and nothing else.
logger.log( .verbose, msg: msg(),
functionName: functionName, lineNum: lineNum, fileName: fileName)
pthread_rwlock_unlock(&logLock)
}
if let logger = swiftLogger, logger.logLevel <= .info {
if let logger = swiftLogger, isSwiftLogging(.verbose) {
pthread_rwlock_wrlock(&swiftLogLock)

This comment has been minimized.

Sign in to view

Copy link
@weissi

weissi May 23, 2019

same here, misplaced critical section

This comment has been minimized.

Sign in to view

Copy link
@weissi

weissi May 23, 2019

same in all the following bits of the code
logger.info("\(msg())")
pthread_rwlock_unlock(&swiftLogLock)
}
}

Expand All @@ -113,11 +127,15 @@ public class Log {
public class func info(_ msg: @autoclosure () -> String, functionName: String = #function,
lineNum: Int = #line, fileName: String = #file) {
if let logger = logger, logger.isLogging(.info) {
pthread_rwlock_wrlock(&logLock)
logger.log( .info, msg: msg(),
functionName: functionName, lineNum: lineNum, fileName: fileName)
pthread_rwlock_unlock(&logLock)
}
if let logger = swiftLogger, logger.logLevel <= .notice {
if let logger = swiftLogger, isSwiftLogging(.info) {
pthread_rwlock_wrlock(&swiftLogLock)
logger.notice("\(msg())")
pthread_rwlock_unlock(&swiftLogLock)
}
}

Expand All @@ -136,11 +154,15 @@ public class Log {
public class func warning(_ msg: @autoclosure () -> String, functionName: String = #function,
lineNum: Int = #line, fileName: String = #file) {
if let logger = logger, logger.isLogging(.warning) {
pthread_rwlock_wrlock(&logLock)
logger.log( .warning, msg: msg(),
functionName: functionName, lineNum: lineNum, fileName: fileName)
functionName: functionName, lineNum: lineNum, fileName: fileName)
pthread_rwlock_unlock(&logLock)
}
if let logger = swiftLogger, logger.logLevel <= .warning {
if let logger = swiftLogger, isSwiftLogging(.warning) {
pthread_rwlock_wrlock(&swiftLogLock)
logger.warning("\(msg())")
pthread_rwlock_unlock(&swiftLogLock)
}
}

Expand All @@ -159,11 +181,15 @@ public class Log {
public class func error(_ msg: @autoclosure () -> String, functionName: String = #function,
lineNum: Int = #line, fileName: String = #file) {
if let logger = logger, logger.isLogging(.error) {
pthread_rwlock_wrlock(&logLock)
logger.log( .error, msg: msg(),
functionName: functionName, lineNum: lineNum, fileName: fileName)
functionName: functionName, lineNum: lineNum, fileName: fileName)
pthread_rwlock_unlock(&logLock)
}
if let logger = swiftLogger, logger.logLevel <= .error {
if let logger = swiftLogger, isSwiftLogging(.error) {
pthread_rwlock_wrlock(&swiftLogLock)
logger.error("\(msg())")
pthread_rwlock_unlock(&swiftLogLock)
}
}

Expand All @@ -182,11 +208,15 @@ public class Log {
public class func debug(_ msg: @autoclosure () -> String, functionName: String = #function,
lineNum: Int = #line, fileName: String = #file) {
if let logger = logger, logger.isLogging(.debug) {
pthread_rwlock_wrlock(&logLock)
logger.log( .debug, msg: msg(),
functionName: functionName, lineNum: lineNum, fileName: fileName)
functionName: functionName, lineNum: lineNum, fileName: fileName)
pthread_rwlock_unlock(&logLock)
}
if let logger = swiftLogger, logger.logLevel <= .debug {
if let logger = swiftLogger, isSwiftLogging(.debug) {
pthread_rwlock_wrlock(&swiftLogLock)
logger.debug("\(msg())")
pthread_rwlock_unlock(&swiftLogLock)
}
}

Expand All @@ -205,11 +235,15 @@ public class Log {
public class func entry(_ msg: @autoclosure () -> String, functionName: String = #function,
lineNum: Int = #line, fileName: String = #file) {
if let logger = logger, logger.isLogging(.entry) {
pthread_rwlock_wrlock(&logLock)
logger.log(.entry, msg: msg(),
functionName: functionName, lineNum: lineNum, fileName: fileName)
functionName: functionName, lineNum: lineNum, fileName: fileName)
pthread_rwlock_unlock(&logLock)
}
if let logger = swiftLogger, logger.logLevel <= .trace {
if let logger = swiftLogger, isSwiftLogging(.entry) {
pthread_rwlock_wrlock(&swiftLogLock)
logger.trace("\(msg())")
pthread_rwlock_unlock(&swiftLogLock)
}
}

Expand All @@ -228,18 +262,22 @@ public class Log {
public class func exit(_ msg: @autoclosure () -> String, functionName: String = #function,
lineNum: Int = #line, fileName: String = #file) {
if let logger = logger, logger.isLogging(.exit) {
pthread_rwlock_wrlock(&logLock)
logger.log(.exit, msg: msg(),
functionName: functionName, lineNum: lineNum, fileName: fileName)
functionName: functionName, lineNum: lineNum, fileName: fileName)
pthread_rwlock_unlock(&logLock)
}
if let logger = swiftLogger, logger.logLevel <= .trace {
if let logger = swiftLogger, isSwiftLogging(.exit) {
pthread_rwlock_wrlock(&swiftLogLock)
logger.trace("\(msg())")
pthread_rwlock_unlock(&swiftLogLock)
}
}

/// Indicates if a message with a specified type (`LoggerMessageType`) will be in the logger
/// output (i.e. will not be filtered out).
///
/// - Parameter type: The type of message (`LoggerMessageType`).
/// - Parameter level: The type of message (`LoggerMessageType`).
///
/// - Returns: A Boolean indicating whether a message of the specified type
/// (`LoggerMessageType`) will be in the logger output.
Expand All @@ -250,6 +288,28 @@ public class Log {
return logger.isLogging(level)
}

/// Indicates whether a swift-log Logger is configured to log at the specified level.
///
/// Note that because there are slight differences in the log levels that LoggerAPI
/// and swift-log define, their equivalence is mapped as follows:
/// ```
/// LoggerAPI: swift-log:
/// .error -> .error
/// .warning -> .warning
/// .info -> .notice
/// .verbose -> .info
/// .debug -> .debug
/// .entry -> .trace
/// .exit -> .trace
/// ```
///
/// For example, a swift-log Logger configured to log at the `.notice` level will log
/// messages from LoggerAPI at a level of `.info` or higher.
///
/// - Parameter level: The type of message (`LoggerMessageType`).
///
/// - Returns: A Boolean indicating whether a message of the specified type
/// will be logged via swift-log.
public class func isSwiftLogging(_ level: LoggerMessageType) -> Bool {
guard let logger = swiftLogger else {
return false
Expand Down

0 comments on commit 312c0c8

Please sign in to comment.