Right, I hear you (and others). Having a global logger used like Log.info("hello world") however means that you won't be able to have extra payload (such as request UUID) automatically attached to all log messages issued by anything that logs whilst a particular HTTP request is being handled.
Just for the record, in synchronous systems thread-local storage can be used to store this extra payload. And for synchronous systems it is possible to wrap all libraries that cross threads and make them propagate thread-local storage appropriately. I do however believe that this is infeasible in Swift because we don't really want to wrap libdispatch, NIO's futures, and everything else that doesn't just synchronously run on the calling thread.
@IanPartridge for Kitura deployments, do you add extra information to all log messages issues by a certain request? If so, how? And what about metrics?
Indeed. We usually wire an explicit Context through to everywhere and you retrieve the logger as well as metrics systems from that context. And you rightly point out that all the problems we're discussing with logging also apply for metrics and other things.
If we allow both "global" and "local" loggers, the problem is that programmers can't easily switch from a global logger to a local one when they want to improve diagnotics. They have to change every single log.
Whereas with a local logger then could, for example, switch from:
common.swift:
internal let log = Log()
file1.swift:
log.info("...")
file2.swift:
log.info("...)
to
file1.swift:
fileprivate let log = Log(file: "file1")
log.info("...")
file2.swift:
fileprivate let log = Log(file: "file2")
log.info("...)
It would work pretty nicely, if it were not for the fact that there's no good replacement for Rusts module path (those look something like my_app::model::sync). #file is often an absolute path, depending on how the compiler is invoked. A #module or #package would be pretty useful here, and I suspect for any logging solution. A structured #sourcelocation would be even better.
on how to obtain an instance of a logger, aka "global" vs "local" loggers, i believe there is a third option which is a global logger factory, which is then used to obtain logger instances in the local scope. this model offers nice separation of concerns where the logger factory handles the configuration aspects and the local logger handles the logging API (eg trace, info, debug, etc) .
so in the local scope, you will do something like:
let logger = LoggerFactory.geLogger("foo")
logger.info("hello world!")
having LoggerFactory a global singleton that is initialized by the application, or a higher level framework like Vapor/Kitura using config files, or programmatically at application start, etc
(class and method names for illustration purposes only)
the key disadvantage of this approach is that it does not allow you to attach context level metadata to log entries and cascade it down. for example, its difficult to attached a "requestId" and "userId" that will then be part of the all logging entries related to that user request, since the various user code and libraries involved in processing such request will obtain their own logger instance with no context. and this is where passing the logger/context object around really shines. that said, while i love the technical attributes of passing the logger/context around, i believe asking users to do so is too high of a bar and not practical in a large ecosystem like the one we want to build. happy to learn about creative ways to achieve that, if anyone has ideas
the java server world has largely adopted this global factory, local instance model through the SLF4J library, and it seems to work reasonably well there. it also jells well with some of the other proposals made in this thread about local handlers. what SLF4J does to address the context challenge is to offer something called MDC which basically is a temporary storage of metadata that is shared between all the code that is processing on the same processing unit (eg a thread), and the logger instances then read the metadata and include it in the log entries as they write them out. in the simplest form of MDC, the metadata storage is thread locals so that everything that is processed on that thread shares the metadata. using thread locals works well when work (eg a request) is guaranteed to stay on the same thread, but obviously systems like NIO require different handling to correctly pass it around as it moves work on/off threads. I am not familiar with dispatch enough to know if an MDC like solution could be made to work with it, so would be interesting to better understand that aspect from someone who is more familiar with it. if they can't play nice together, we can consider building this in stages, where we address the context aspect of work done through dispatch if/when the core team gives us additional extension points to make it work
There is a Java framework called Ratpack, that is based on Netty, and its API is not very dissimilar to Vapor in that it is future based, and makes no guarantees about a given request being completed on the same thread.
It does however have something called MDCInterceptor which allows you to use MDC as you always would: Documentation, Source code.
Besides the obvious lack of context, this is a really nice and lightweight solution, and I came with the same idea in my implementation of LoggerManager factory:
Appenders allow plugging different implementations.
I also gather some file / lineno information.
Example:
LoggerManager.configure(appenders: [LogstashAppender()])
let logger = LoggerManager.getLogger(name: "test")
logger.debug("test")
I'm wondering about the hierarchical contexts, to have more structured logging, though.
Surely adding context: String? = nil to the logging API is not a huge burden to anyone. Well designed subsystems could arrange to accept and pass around such a context string. Users and library authors who can't be bothered could ignore it; those of us who actually need to debug our systems would probably use it.
Logging level should be accompanied by an optional category, making it possible to select (for example) all dataloss level messages in the networking category, or all normal level messages in the user login category. If no category is provided for a given logging call, it matches all/no categories, depending on the query.
The defined levels and categories should be enums so that the abstract logging framework can be shaped to the specific application.
@neallester the challenge with making context an argument of the logging api, is that unless there is an implicit way to retrieve the context, such argument needs to also be added to most/all other functions of the program and libraries, since one would want to log from potentially anywhere in the program. as for ignoring context, when the context carries critical information like tracing (eg requestId) log entries become useless without it: you are left to do timestamp matching which is non-deterministic in a system that does concurrency, such as a server. i take your point that in a small, well contained system, passing context around between functions is achievable, but imo at an ecosystem scale this will prove to be "too hard" and not pragmatic
Historically, my approach has essentially been one of the hybrid forms - a global Logger object is accessible which provides a "generic" logging facility, with an extension that supports adding context (typically Vapor's Request object) and utility methods such that individual request handler classes would do private let log: RequestSpecificLogger and do something like self.log = req.make(Logger.self).logger(forRequest: req) in their init (the latter call being necessary due to design limitations in Vapor's Services framework). The logger(forRequest:) method then saves off the Request object and chains it to the log(request:level:message:file:line:) method(s) on the "global" Logger, which through the extensions that take a Request input know how to obtain appropriate context such as a request ID, and ultimately funnel the contextualized log message down to Logger's original log() methods.
This approach is great if the context you want to add for any given log message is consistent across most or all of your implementation, and the same "fake currying" technique allows for creating per-subsystem loggers and other various levels of specificity.
The drawbacks, of course, are the additional layers of complexity and leaving the burden of making sure the appropriate logger object is used in the appropriate places on the library/app author. I'm not entirely sure what a generic form of this approach would look like, but I wanted to put it out there as a variation on some of the approaches suggested so far in this thread.
Sure, but it doesn't make it meaningfully harder either.
I would strongly encourage reducing the scope of the discussion here by aggressively considering some proposals as "out of scope" for an initial prototype. For large group discussions with many stakeholders it is very easy to become buried in the pile of great features that people love from other programming ecosystems and to attempt to satisfy them all on the first go. This is a recipe for failure.
We'll likely be best served by identifying which things have to be decided correctly up front and working on those initially, while ensuring we do not prevent any of the other, richer, features we want from emerging. I'd argue that logging contexts fall outside the "must get right the first time" category. They can be added after the fact with small API changes, and are not mandatory for many use cases. Additionally, they are themselves a quite substantial feature that deserves the proper focus of this WG, not something that we should assume is simply solved by throwing a String around.
Thanks @tomerd, that's a good summary and as you point out, the MDC approach won't work if not all thread-crossing libraries collaborate which I don't think will happen in the Swift space. Dispatch doesn't do that today (on Linux) and we also don't want to wait for a year.
@gps The issue with MDC is that it needs to have special support from all involved libraries that do cross threads. In Swift I think this is unrealistic as we first and foremost would all need to switch to a Dispatch wrapper that propagates the context. I think MDC as is a necessary crutch which implicitly propagates the context in a 'magic' and hard to understand way. When it was designed we lived in a thread-per-request world and thread locals seemed like a good solution. And in a mostly blocking world, thread-locals do a fine job, when the Java world moved more and more toward non-blocking they just had to make MDC work by having the libraries all propagate the context implicitly like the thread-locals did before.
I wanted to discuss the explicit passing of context in Swift because we have a fresh start and because lots of Cocoa is already asynchronous so I think our issue with automatic context propagation is harder than it ever was in Java. Just to point it out: There is os_activity which does propagation of some sort of context through Dispatch/XPC/... but it's Darwin-only and is only documented in the manpages.
@IanPartridge queue/thread locals can indeed be used to hold the context but something needs to put it in there and that's the complicated part. So every queue/thread crossing library needs to forward the context.
After thinking about this a bit last week and discussing with @johannesweiss, I think the best solution would be a global Logger that allows you to pass an optional context.
Logger.info("foo")
Logger.info("foo", ctx)
In cases where you can't easily pass this context (such as a computed property getter), you could just use the global log method. For cases where you can get access to the context, passing it would enhance your log output.
As @johannesweiss has mentioned, it seems there is no way in Swift to relate asynchronous work w/ a given "activity" (i.e., request). For example, if an incoming request triggers an async database query, there is no way for SwiftNIO to know that static logging done as a result of the async database query should share a context with the request that triggered it. The only way to form a relation between the request and other async work it performs is with a context.
The good news is that if SwiftNIO can provide general-purpose context type, this would be useful tool for solving other problems (such as metrics). Frameworks built on top of NIO would be expected to assist in passing around this context as much as possible.
I agree that omitting an argument of the type we are discussing (e.g. context, subsystem) from the logging API doesn't make adding a context or subsystem value to the log message meaningfully harder. However, what is harder is arranging for all log messages the system emits to format those values in a consistent manner. Thus, I think there is value in including separate parameters in the API, especially since swift parameter defaults can make it easy for users to ignore those parameters if they want to. Plus the documentation for those parameters in the API can describe how well behaved libraries (and applications) are to use the parameters. That documentation can also point out to users and library authors how valuable information like request context is during debugging to encourage them to go to the trouble of using it. Finally the parameter names (for information which must be passed around) can be adopted as standards by users and library authors making those systems easier to design and understand.
I find that having a convenient way of passing in name/value pairs to my logging system without having to format them in application code encourages me to think about what data would be useful when reading the message and encourages me to actually include it with the message. It would also enable application developers to format all of the name/value data in their log messages consistently system wide.