Logging

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.

3 Likes

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.

5 Likes

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

2 Likes

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.

5 Likes

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

2 Likes

Sounds good to me!

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

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.

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?

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.

1 Like

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.

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

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

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

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

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.

2 Likes