Logging


(Johannes Weiss) #99

No, global variables are not thread-local but you can create thread-local variables and they often do feel like globals sometimes even without the programmer noticing.


(Johannes Weiss) #100

Yes, passing the context around everywhere does solve all the issues but is very invasive and as @tomerd pointed out probably not practical...


(Johannes Weiss) #101

Right, let me just propose some actual code and a way with which we could proceed with something that people could use today.

As @tomerd summarised, we have two options: explicit or implicit logger/context passing (which I initially called local and global loggers, but explicit v. implicit is better terminology). Whilst explicit context passing would solve all the logging context issues it's probably too invasive for the real world without language support. We also don't want to delay having a shared logging solution so I don't think it's useful to wait for either language or Dispatch support.

That does - as stated before - mean we can't have the correct logging context available in all places and we will need to live with that. We can however declare logging context to be a responsibility of the concrete logger implementation and have it do best effort. That would mean that Vapor and Kitura might use logging systems that work completely differently but crucially share an API. For synchronous systems, it could just use a thread-local. For asynchronous systems the context needs to come from elsewhere either passed around or hung off say the 'request' type. In both cases this will mean that the logging context isn't necessarily reliably available everywhere. Especially not in asynchronous systems that call out to external libraries which are not prepared to get a logger passed explicitly.

So let's start with some code:

/// The most important type, the one the users will actually interact with and for example write:
///
///     let myModuleLogger = LoggerFactory.make(label: "example.myproject.FooModule")
///     class MyClass {
///         func something() {
///             myModuleLogger.warn("something isn't a great function name")
///         }
///     }
public protocol Logger {

    public init(identifier: String)

    /// not called directly, only by the helper methods like `info(...)`
    // EDIT2: Should change to `message: @autoclosure () -> String`
    public func _log(level: LogLevel, message: String, file: String, function: String, line: UInt)

    /// This adds diagnostic context to a place the concrete logger considers appropriate. Some loggers
    /// might not support this feature at all.
    public subscript(diagnosticKey diagnosticKey: String) -> String? { get set }
}

extension Logger {

    // EDIT2: Should change to `message: @autoclosure () -> String`
    public func info(_ message: String, file: String = #file, function: String = #function, line: UInt = #line) {
        self._log(level: .info, message: message, file: file, function: function, line: line)
    }

    // EDIT2: Should change to `message: @autoclosure () -> String`
    public func warn(_ message: String, file: String = #file, function: String = #function, line: UInt = #line) {
        self._log(level: .warn, message: message, file: file, function: function, line: line)
    }

    // EDIT2: Should change to `message: @autoclosure () -> String`
    public func error(_ message: String, file: String = #file, function: String = #function, line: UInt = #line) {
        self._log(level: .error, message: message, file: file, function: function, line: line)
    }
    // lots of to bikeshed more _log methods
}

public enum LogLevel {
    case info
    case warn
    case error
}

/// The second most important type, this is where users will get a logger from.
public enum LoggerFactory {
    // this is used to create a logger for a certain unit which might be a module, file, class/struct, function, whatever works for the concrete application. Systems that pass the logger explicitly would not use this function.
    public static func make(identifier: String) -> Logger {
        return LoggerImplementation.loggerType.init()
    }
}

/// Ships with the logging module, really boring just prints something using the `print` function
public struct StdoutLogger: Logger {
   [...]
}

/// This is the place to select the concrete logger implementation globally. The selection of the concrete logger type
/// that is used globally should only be done by the application itself (and not by libraries).
///
///     LoggerImplementation.loggerType = MySuperFancyLogger.self
public enum LoggerImplementation {
    private static var _loggerType: Logger.Type = StdoutLogger.self
    public static var loggerType: Logger.Type {
        get {
            return self.lock.withLock {
                return self._loggerType
            }
       }
       set {
            return self.lock.withLock {
                self._loggerType = newValue
            }
       }
}

That way whenever someone needs a logger, they can just LoggerFactory.make(identifier: ...) and have a logger which offers pretty much the convenience of a truly global and static Log.info("something"). But asynchronous systems like Vapor could carry around a Logger instance in their HTTPRequest.

So in an asynchronous system like Vapor you might write

myRequest.logger.info("something")

and Vapor libraries might never actually use the LoggerFactory as they always get the logger explicitly through the request.

To add that logging context, Vapor internally could run similar to this

currentRequest.logger[diagnosticKey: "request_id"] = UUID().description

By the virtue of hanging the logger of the HTTP request, Vapor could explicitly pass the logger around in its own libraries and to all external libraries that support it. Sure, any library that doesn't accept a logger will not have any logging context associated.

Synchronous systems could make their concrete logger implementation store the diagnostic context in a thread-local instead of the logger instance itself.

I should mention some tradeoffs I made here:

  • only one String typed message, no fanciness like os_log. Why? Because a) we can always extend that later b) this will not be the fastest implementation of a logger anyway we'll need to take locks, go through existentials etc to log c) this seems to mostly be what people use today
  • no configuration of log-levels etc. This is all the responsibility of the concrete logger implementations
  • a lot is down to the concrete implementation of a logger
  • EDIT: I should point out that I didn't make the message @autoclosure right now and there's good arguments it should be but that'd lead to an allocation as the concrete logger can't be inlined because it's not known at compile time... EDIT2: @Joe_Groff said that if an API relies on an efficient implementation @autoclosure this could be prioritised; therefore I think we should use it here.
  • it's the hybrid model described above

Pros:

  • we can start with this today
  • ease of use as the logger is reachable from anywhere
  • can kind of support explicit logger passing where available (if one controls the whole project)

Cons:

  • no reliable propagation of log contexts
  • everything is Strings
  • any Logger implementation will likely take locks (even if nothing turns out to be logged) and do syscalls (only if something's logged)
  • using a synchronous system's concrete logger (which might store the logging context in a thread-local) with an asynchronous system will lead to weird stuff and the logging context is propagated to random requests :slight_smile:

To be clear: This is by no means complete or what I consider to be a perfect API or anything like that. I just wanted to propose some concrete code. To get slightly less theoretical I would ask anybody to come forward with features they consider to be absolutely necessary which cannot be supported by this API. I hope that through iteration we arrive at something that anybody can live with and we can start implementing that. How does that sound?


(Tanner) #102

I would be happy with something like the API you proposed here. I think it would get the job done effectively.

But there is one thing I miss from this implementation:

If we were to create a generic Context or Activity type whose sole purpose was to capture and relate context, we could re-use such a type for many applications going forward. In other words, logging isn't the only thing that benefits from explicit contexts. The solution above allows for explicit contexts with logs by passing around an initialized logger. This is great, but if we also want explicit metrics, then we now need to pass around two things.

If I were to propose an API, I would do something very similar to yours, but with one small change regarding context:

public protocol Logger {
    public func log(_ level: LogLevel, _ message: String, _ ctx: Context?)
}

public enum LogLevel {
    case info
    case warn
    case error
}

public enum Log {
    private static var logger: Logger?

    public static func info(_ message: String, _ ctx: Context? = nil) {
        logger?.log(.info, message, ctx)
    }

    public static func warn(_ message: String, _ ctx: Context? = nil) {
        logger?.log(.warn, message, ctx)
    }

    public static func error(_ message: String, _ ctx: Context? = nil) {
        logger?.log(.error, message, ctx)
    }
}

public struct StdoutLogger: Logger {
   ...
}

// pseudo framework code

final class VaporResponder: HTTPResponder {
    let app: UserApplication

    func respond(to req: HTTPRequest) -> Future<HTTPResponse> {
        req.ctx["unique"] = UUID().description
        req.ctx["start_time"] = Date().description
        return app.respond(to: req)
    }
}

// user example

Log.logger = StdoutLogger()

router.get("hello") { req in
    Log.info("Hello called!", req.ctx)
    return "world"
}

// log would look something like

[ INFO ] Hello called! (unique: ..., start_time: ...)

That said, I'm definitely not against @johannesweiss's example. I think that would work quite well. Just wanted to share some ideas about the utility of a generic Context type.


(Johannes Weiss) #103

disclaimer: What I'm proposing in this post is not adding to the logging discussion itself. I'm trying to make a point that we don't need to add Context to the Logger but can design Context later without losing functionality. Please feel free to skip this post entirely (apart from @tanner0101 of course :upside_down_face:) .

Thanks @tanner0101 that's clearly something that's not possible with just what I proposed. The issue I see with what you're proposing is that concrete logger implementations for some systems might store some kind of context in thread-local variables or other places that work. To then support the API you propose they first need to merge the two contexts. Not the end of the world but also not great... What if there's two values for the same key? Also, we would add complexity to logging upfront which probably makes it harder to design.

One way out of this dilemma would be to flip it around for systems that pass some (to be designed at a later stage) Context object around. They could retrieve the Logger instance from the Context. Ie.

func handleNewRequest(uri: String, queue: DispatchQueue, serverContext: Context) {
    var clientContext = serverContext
    clientContext.requestUUID = UUID()
    clientContext.log.info("AAA: about to handle request for \(uri) on \(queue)")
    queue.async {
        handle(uri: uri, context: clientContext)
    }
}

func handle(uri: String, context: Context) {
    context.log.info("BBB: now handling request for \(uri)")
}

As I said I don't think we should discuss here how Context works or how it should be designed because we can separate that from the logging discussion in my eyes.

But obviously what we do want is that both log messages (AAA: ... and BBB: ...) should have the request UUID attached which seems quite hard because the logger is setup before the requestUUID is set up.
The way we can design ourselves out of the problem is that Context could internally store its values as closures (Context) -> ValueType (in the logger example (Context) -> Logger). Then when you invoke context.logger, Context could pass itself to that closure so we can decorate the Logger before returning it. Ie. something like

var logger = MySuperCoolLogger()
logger.logLevel = ...
// making up API here which would allow to set closures in a context rather than just values
context.set(LoggerKey.self, { context in
    var decoratedLogger = logger
    decoratedLogger[diagnosticKey: "request_uuid"] = context.requestUUID
    return decoratedLogger
})

so when the user calls context.log that above closure would be run which will decorate the logger which will lead context.log.info(...) to be decorated with the request UUID and possibly other things.

As I said, this is just an idea how things work but we do use a model very very similar to this and so far it seems to work.

Let me know what you think.


(Tanner) #104

I think that's a good compromise. I'm behind this plan :+1:


(Johannes Weiss) #105

Ok, thanks everybody and sorry for the radio silence. I'll get an initial version together and pitch this to the Swift Server Work Group so we can start the discussion with real compiling code in due course.


#106

@IanPartridge @johannesweiss should we move this discussion to the new pitches category?


(Ian Partridge) #107

Sounds good to me!


(Alexander Momchilov) #108

Isn't the local logger's functionality a subset of the global logger? Just make a local logger, assign it to a terse global variable (e.g. log), and boom, you have a global logger.

Perhaps you can add in an option in the initializer which determines if you want an internally synchronized logger (e.g. for a global logger) or not (e.g. for a local logger dedicated to a single worker thread).


(Alexander Momchilov) #109

I wouldn't give much attention to "12factor apps". They advocate for lots of silly things.

Configurations through environment variables? Are you kidding? What if I want a config whose value is an array. Then what? Comma seperate string? Smh... How do you change a config at run time with restart/redeployment of your service? Perhaps you could inject a command to overwrite an env var using gdb, lol.

More to the point restricting: logging to only ever be unbuffered output stdout is a terrible idea. Rather than some simple mechanism in your app, written in a nice language (e.g. Swift), you have to deal with some contextual mess, with launch scripts and other such crap.


(Alexander Momchilov) #110

Could you elaborate on why testing log messages would be useful? All I can picture is the sheer redundancy of wanting to rephrase a log message's wording, and having to do it twice, once in the prod code, and once in the test. To what end?


(Neal Lester) #111

Could you elaborate on why testing log messages would be useful? All I can picture is the sheer redundancy of wanting to rephrase a log message's wording, and having to do it twice, once in the prod code, and once in the test. To what end?

Log messages are a specified system output and should be verified when written. It doesn't take any more time to do that in a test than running the program and watching the console. Just when I think I'm being silly spending my time cleaning up broken log output tests after a minor change, I discover a logic change accidentally eliminated a log message or that I've accidentally eliminated important diagnostic information from a log message. Once an application is in production changing log messages can break monitoring systems and other processing pipelines so it isn't something one wants to do accidentally and not notice.


(Lukas Stabe 🙃) #112

I wouldn't be so dismissive about things you seem to not be very familiar with. Smh...

I didn't know 12factor, but their guidelines seem pretty reasonable given the constraints laid out in their introduction.

Especially "[...] Are suitable for deployment on modern cloud platforms, obviating the need for servers and systems administration [...]". Config through env vars is a very common pattern on cloud/container platforms, and rightfully so, imo.

Also I don't think anyone here advocated for only allowing logging to stdout. Just that logging to stdout is very common and our solution should function well in that context.


(Johannes Weiss) #113

Yes, if and only if the logger is also thread-safe. That might seem like a trivial 'of course' but there are implementations where the logger itself is a value holding only the log-level and having a firehose to the backend. That way you could evaluate whether to lock without a lock/atomic(*).
But to be honest I now think that the terminology I chose just wasn't very good. It has become apparent that not everybody will switch to explicitly passing the logger around so all(?) logger implementations will just take a lock/atomic for the log level and we have to live with it.

(*) we don't have a memory model today but for 'relaxed' semantics atomics (which are enough for a log-level) we can just use the C11 atomics with an atomic allocated on the heap (like we do in NIO). Implementing a fire hose (all threads log in to the same queue where there's one thread consuming and then actually logging it (ie. write to stdout/file/...)) is currently not really possible in Swift because the lack of a memory model. We could do it in C or just trust the compiler doesn't do anything too bad ;)


(Simon Pilkington) #114

This seems fine when you control everything and will have access to the context to then get access to the logger. But particularly with higher level libraries and applications that is really unlikely to be the case and it is further unlikely that we could get the ecosystem into a state where every library accepts a compatible context for logging. IMO, we should keep the requirements for libraries as simple as possible to encourage adoption.

func handleNewRequest(uri: String, queue: DispatchQueue, serverContext: Context) {
    var clientContext = serverContext
    clientContext.requestUUID = UUID()
    clientContext.log.info("AAA: about to handle request for \(uri) on \(queue)")
    queue.async {
        handle(uri: uri, context: clientContext)
    }
}

func handle(uri: String, context: Context) {
    context.log.info("BBB: now handling request for \(uri)")
    ThirdPartyLibrary.doSomething()
}

Any logging from the third party wouldn't have any context and that seems like a miss.

I would favour something functionally closer to a stack of contexts, allowing someone to say for now - on this thread if that what the implementation chooses to do - use this logging context.

func handleNewRequest(uri: String, queue: DispatchQueue) {
    var clientContext = Log.context(keyedBy: LoggingKeys.self)
    clientContext.set(UUID(), forKey: .requestUUID)
    Log.with(clientContext) {
      Log.info("AAA: about to handle request for \(uri) on \(queue)")
      queue.async {
        Log.with(clientContext) { // unfortunate duplication to handle potentially moving threads
          handle(uri: uri)
        }
      }
    }
}

func handle(uri: String) {
  Log.info("BBB: now handling request for \(uri)")
  ThirdPartyLibrary.doSomething()
}

(Simon Pilkington) #115

And also sorry for being late to the party on this thread...


(Johannes Weiss) #116

Apologies @tachyonics, I totally forgot to reply here :frowning: but I believe the proposal that I just posted would cover what you suggest.


(Johannes Weiss) #117

Lots of interest in this pitch IMHO clearly shows that there is need for a logging API. I finally (apologies for the delay) managed to write up a Server Logging API Proposal which you can find in the Server/Proposals category.
For feedback about my proposal (or the early first bits that I posted as code snippets in this thread) please reply to the proposal directly.


closed #118