[Discussion] Server Logging API


(Nathan Harris) #12

I definitely would like to see this provided by the library - but it can wait until the underlying design is done.

EDIT: As I think we should keep the discussion on the core foundational API, and additional feature requests / discussions happen in the original pitch thread or we create new ones.


(Gwynne Raskind) #13

This is an amazing start! Some thoughts:

  • I've found the ability to attach multiple LogHandlers (or the equivalent) to be of considerable use in other logging systems, especially when hooked into whatever configuration system is in use.
  • I wish we didn't need to attach a bare-bones handler by default. I agree that making the failure to do so fatal creates an excessively high barrier to entry, but it's something very easy to just leave in place and never bother with later. Could we possibly print a warning when that behavior happens so users get nagged about it? (And, of course, permit explicitly specifying the StdoutLogHandler to say "yes I really just want this" and silence the warning.)
  • I like the subscripting for metadata, but I think they would be better CustomStringConvertible than straight-up String, or maybe a new CustomLoggerMetadataConvertible protocol if the former proves difficult for whatever reasons. The flip side of this is it potentially hits performance issues - I don't know what unwrapping existentials at runtime costs these days versus static dispatch.
  • I think an MDC API is overkill at this layer, it's certainly easy enough to add such a layer if one wants it. Maybe something that could be built as an optional add-on.
  • In general more control over how the metadata gets formatted might be worthwhile. You linked to the OSLog proposal already; that has some very interesting ideas for possibly making the metadata keys strings after all, such that the interpolation would be used to generate already-well-formatted strings.
  • I do like the idea of namespacing things - Logger.Level etc. strikes me as more "Swift-y" than LogLevel.

(Nathan Harris) #14

I didn't include that in my snippet proposal above, but I definitely agree with this.

Personally, this is something I'd like the library to have an opinion on and provide me - but we can do it as another abstraction provided by the library, rather than baked into the lowest implementation.

I get the feeling that we should let LogMessageHandler/LogHandler should be responsible for the formatting and just receive passed information metadata, identifier, level, etc. - perhaps some sort of Context type?


#15

that is exactly the design. LogHandler (ie the specific logging implementation) determines formatting


(Gwynne Raskind) #16

This post has several different not-interrelated bits, so I've broken it into sections:

Formatting

On reflection, I find myself oddly ambivalent about how I think formatting - especially for metadata - should be handled. Consider these examples:

protocol CustomLoggerMetadataConvertible {
    var descriptionForLogging: String { get }
}
extension CustomLoggerMetadataConvertible {
    /// Default to simple description for all objects
    var descriptionForLogging: String { return String(describing: self) }
}

struct MyComplexContextuallyImportantThing { /* ... */ }
extension MyComplexContextuallyImportantThing: CustomLoggerMetadataConvertible {
    var descriptionForLogging: String { return "\(/* machine-parseable logging format */)" }
}
extension MyComplexContextuallyImportantThing: CustomStringConvertible {
    var description: String { return "\(/* human-readable format */)" }
}

//...
let context = MyComplexContextuallyImportantThing(/*blah*/)
myLogger[metadata: context]
// OR, remove the `CustomLoggerMetadataConvertible` conformance and:
myLogger[metadata: "\(context./*logging format*/)"]

The two different ways of setting the context as metadata have some interesting tradeoffs:

  • The protocol conformance allows the same magic that CustomStringConvertible does for String.init(describing:): Each type knows how best to represent itself for logging and can do so without that knowledge leaking into the logger setup.
  • On the other hand, the protocol conformance represents (a very constrained form of) spooky action at a distance - the code setting the metadata has no control over how a given object may represent itself and changes in that representation may break things.
  • Using a new protocol instead of CustomStringConvertible allows an object to represent itself differently inside a logging context than outside, and the default implementation avoids needing anything other than the conformance declared fro objects that don't care.
  • You still end up needing the conformance, unless the subscript takes Any and does as? checks for conformance at runtime.

This is ultimately the same problem as shows up in any use of conformances - the decision about where the control should be is complicated. I see the metadata subscript as having several possible signatures:

// Strings are represented directly
public subscript(metadataKey metadataKey: String) -> String? { get set }

// `String(describing:)` is used
public subscript(metadataKey metadataKey: Any) -> Any? { get set }

// Same as previous, but also checking for a `CustomLoggerMetadataConvertible` conformance, and using it if present
public subscript(metadataKey metadataKey: Any) -> Any? { get set }

// Only conforming types may be used - good thing `CustomLoggerMetadataConvertible` doesn't have Self or associated type requirements!
public subscript(metadataKey metadataKey: CustomLoggerMetadataConvertible) -> CustomLoggerMetadataConvertible? { get set }

// Same as above, but using `CustomStringConvertible` instead of a separate protocol
public subscript(metadataKey metadataKey: CustomStringConvertible) -> CustomStringConvertible? { get set }

I'm not sure where I personally land on this one. I like CustomLoggerMetadataConvertible (name open to debate of course :slight_smile:), but I don't like having to conform all metadata I might use to it and I also don't like the idea of the accessor having to take and return Any. Maybe have two overloads, where the second one takes String or CustomStringConvertible, though that obviously complicates LoggingMetadata's internal representation.

LogHandler API

Log handlers need func openLog(file: String, function: String, line: UInt) (maybe without the parameters, I'm not sure how useful they are in this context) so logs that care about/need initialization after init() but before the first log message aren't forced to maintain a "did I do my extra setup yet" flag.

There's also potential room for func closeLog(/* etc */), with the caveat that a log handler can never rely on the close function being called since it wouldn't be in the case of sudden, abnormal, or crashing termination. ... In fact, come to think of it, that caveat is so significant and so easy to accidentally ignore (there's certainly no way for the compiler to enforce it!) that it's probably better not to provide a close method at all. I'm only leaving the thought in this post for the sake of transparency of thought process (in other words I don't want anyone to accuse me of not thinking of it :laughing:).

Custom log levels?

An additional issue I find I run into in real-world usage is that the predefined log levels provided by a given logging library are almost never perfectly suited (often not even well-suited) to the needs of my project. For example, in Vapor-based services I tend to use LogLevel.custom("database") to enable separating (often very noisy) database query logging from other logging. Obviously this is difficult to make cleanly extensible in Swift. I find Vapor's .custom(String) API undesirable due to being stringly-typed - I always end up wrapping it in a non-trivial amount of extra logic to avoid accidental misuse, and that still doesn't address the problem possible memory and performance issues from adding a case with a payload to the level enumeration.

The problem is I don't know what an alternative to the stringly-typed case would be. Even if pure Swift supported "open" enums (which it doesn't), conflicts between custom cases would be immediately apparent between modules (which is part of why open enums aren't a thing, if I recall!). This is also a problem with the stringly-typed method. Namespacing of log levels would tend to be painful to use, and reading the results as much or more so. This might be addressable by making LogLevel a struct (in the style of OptionSet) instead of an enum and working out a means by which conflicts would be minimized.

The real question is, at that point, is it worth the complexity? I find that it is, but I don't know that it would be for the majority of projects.

Logging configuration

This brings me to the other feature I find myself missing consistently in Vapor's support that this proposal doesn't yet address: Configurability of log levels. This covers:

  • Do I log messages at this level at all?
  • Are log levels strongly ordered (so that a currentLogLevel of warn covers both warn and error but nothing else) or individually controlled (such that the current level would be represented by something like Set<LogLevel>)? If the latter, is the "level" more accurately described as a "type"?
  • Is there value in an additional field such as "subsystem" and/or "category" (as found in os_log()) for providing (even) more control?
  • Should this decision be left up to LogHandlers or be encapsulated by the Logger?
  • Is "current level" global, per-Logger, per-LogHandler, or something else?

I'm not sure whether or not this is even in scope for this proposal, but I thought it worth mentioning. If it is, I do have some thoughts on API for it, but it's not sensible to take the time for that unless it's in scope and until some of the questions are discussed.

And so on

I could keep going with more ideas, there's so many things a really "robust" logging API might do, but I think I'm already on the knife edge of the complexity threshold - one of the explicit design goals of having this in SSWG is to make it both simple and robust, after all.

Apologies to anyone whose thoughts I've repeated without giving due credit - I didn't read the entire thread thus far exhaustively; I've only skimmed.


#17

to add a bit of background, the core idea behind the proposal is offering a standard logging API, not a standard logger implementation. in the server ecosystem, you want strong decoupling between the logging API and the implementation for two main reasons:

  1. you dont control the operating system and architecture, so may want to plug-in architecture/os specific logger implementation when writing cross-platform systems, eg use os_log based logger implementation on darwin, and something else on linux

  2. large enough server deployments typically integrate with log indexing systems such as splunk, or elk, or similar systems that enable scalable monitoring / operation of the fleet. the integration with such systems may impose certain requirements on how log entries are dealt with, for example what format they are written in (so they are easier to index), or if they are written to files, or posted over HTTP to a remote sever, or put in a queue, etc. this means that making opinionated logging decisions at the calling site (API) can get in the way of the application trying to integrate with such systems. similarity, if the application dependencies (ie libraries) make opinionated logging decisions or assumptions, that will get in the way of the application trying to integrate with such systems.

for this reasons you want to:

  1. define a logging API that is unopinionated enough so that all libraries in the ecosystem can rely on it without getting in the way of composition

  2. define a pluggable logging system that allows application to make the opinionated decisions by bootstrapping with a logger implementation that fits their operational model. eg some may want to write to files in a human readable format, but others may want to send to one of the log indexing systems mentioned above in json or key-value format. similarity, you may want to do different things when developing/debugging vs when in testing vs when in production

tying this back to the proposed API:

  1. Logger is the unopinionated calling site API which users are expected to interact with the most. its designed for libraries (eg database drivers, web frameworks) developers so they can provide transparency to their users, as well as applications developers to log throughout their application code

  2. Logging is the pluggable logging system, designed to allow the application owner to plug the logger implementation suited to their operational needs. this is done by calling Logging.bootstrap in the application main

  3. LogHandler is the API designed for developers of logger implementation, aka logging libraries. iow, this API is not designed to be used directly by library (eg database drivers, web frameworks) or application developers. there will probably only ever be a handful implementations of this API in the ecosystem

one other point of reference for the reviewers of this proposal are the unit tests (GlobalLoggerTest, LocalLoggerTest). they include different implementations and usage of these APIs that could answer some/many of the questions raised on this thread


Metrics
Client side Prometheus implementation
(Neal Lester) #18

I suggest adding the parameter

data: [(name: String, value: CustomStringConvertible?)]? = nil

to each of the methods used to emit a message (i.e. trace(), debug() etc.). This makes it easy for the developer to provide additional information with the message structured in a way that enables the LogHandler to format it consistently. The only real "gotcha" for application developers would be that the CustomStringConvertible would need to be thread safe or value types. Of course, LogHandlers would need to extract their strings and release that reference promptly. I find having the "name" and "value" labels useful when specifying data which contains several data tuples but of course that's personal taste.

I also think its worth considering that "context" is one or more name/value tuples that a Logger prepends to any data received with each message. Adding a feature

public struct Logger {
     forwarder (level: LogLevel, context: [(name: String, value: CustomStringConvertible?)]? = nil) -> Logger {}
}

which returns a Logger that prepends its context to the data and forwards the message along to its parent (or filters it) could also be useful.

A design which enabled adding arbitrary log levels through extensions would be desirable, but the non enum based implementation required might introduce too many issues. Without doing the analysis needed to really understand the trade offs, I think I would prefer library fixed levels. However, I would suggest a somewhat more granular set of options:

↓ Levels that would generally be activated in development, maybe in testing

  • trace
  • debug

↓ Levels that would generally be activated in testing, maybe in production

  • info: normally expected event
  • warning: an event which may or may not indicate a problem

↓ Levels that would generally be activated in production

  • business: normally expected event whose entry is consumed by other systems
  • error: an event which indicates a problem
  • emergency: the system requires immediate attention

The task of isolating logging output by subsystem strikes me as orthogonal to log levels. Having application developers provide different loggers (set to different log levels) to different subsystems strikes me as a simpler approach than enabling the log system to filter by both level and subsystem. The "forwarder" function I propose above would make this easier.


(Dante Broggi) #19

One thing I see about these APIs is that they violate the recommendation of Ole Begemann: Don’t use CustomStringConvertible as a constraint, because "anything is printable".


(Gwynne Raskind) #20

Yeah, that was one of my concerns with using CustomStringConvertible - though in a "logger" context, "anything is printable" may actually be the desired behavior. I'm not sure if that really applies to metadata, though, especially when the desire is specifically to have metadata that can be used to machine-parse the log files.


(Neal Lester) #21

sure, but with CustomStringConvertible the common case:

var index = 2
[(name: "index", value: index)]

is a bit nicer than

[(name: "index", value: "\(index)")]

and you can still use string interpolation or String(description:) on those rare occasions when you have something which is not CustomStringConvertible.


(Neal Lester) #22

I really like having "file" and "function", but I would prefer not to include "line". File + Function + Message by themselves allow efficient navigation to the source of the message in the code so the "line" parameter just generates noise which will change frequently either making writing tests a bit more burdensome or generating a lot of test failures which need to be fixed. Granted, the line# could be omitted by a testing LogHandler.


(Xiaodi Wu) #23

I think here we have a very fundamental difference of opinion, and without addressing any other points of style or design, this needs to be addressed first:

I understand that, from your perspective, it must not be possible to use the logging API without choosing a logger.

I disagree. I proceed from the basis that, for this logging API to be learnable, teachable, and usable for beginners (and beginners we all were at one point, and a general API for logging must accommodate them), it absolutely must be possible to log something somewhere without knowing what a Logger, Logging, or LogHandle is. The barrier to logging something should be as low, if not lower, than printing.

I think all the remaining API questions would unfurl very differently on the basis of the settling this point.


(Neal Lester) #24

You will commonly want a session ID id as well in order to trace the users actions before the specific request. In many deployments you'll also need an instance ID for the application and/or an application ID if you have different applications (sharing common libraries) feeding into the same logging system.

The Logger manages filtering and adding context, the handler takes care of formatting and posting, right?


(Pedro José Pereira Vieito) #25

If we could get info about the calling module (even adding to Swift a new #function-style parameter, #moduleName / #moduleIdentifier) I think it would be great to add a global logger.

I don't see the need to have Logging / LoggingSystem and Logger separated. Logging.make() should simply be Logger.init(identifier:) and Logging.bootstrap() should be something like Logger.addHandler().


(Lukas Stabe 🙃) #26

The single global variable per module might be easy enough, if it were not for this:

There is a global default logger(-ish) already available. It's called print(...), and I know that I at least (and I suspect many others) would probably resort to just using that "just for now" and then never get around to changing it to something proper.

I think it is crucial this API is as frictionless to adopt as possible, and to do that it needs to be a drop-in replacement for print. If we could get that to carry module information next to file, function and line (structured SourceLocation :pray:) that would be great, but even with just the source location info we have, that would bee good enough, imo.


(Simon Pilkington) #27

Thanks @johannesweiss and @tomerd for putting this together.

A couple of initial things-

TL;DR

  1. I would recommend splitting Logging.make into-
    1. an API the application can call to create a LogHandler implementation to explicitly pass around after having bootstrapped the logging system (what the API is currently).
    2. an API to create a proxy for libraries to create a static logger that resolves the LogHandler implementation at log time to avoid instantiation/bootstrap ordering issues.
    3. an API to create a logger from a logger for libraries to create a Logger to explicitly pass around; again the library doesn't need to understand if the logging system has been bootstrapped - the existing logger has either been passed from the application who ensured bootstrapping occurred or is a proxy created by itself or another library.
  2. There is a potential performance impact of this for logging from libraries but potentially is worth it if the framework is more robust against incorrect bootstrapping.
  3. The ability for an application to "lock" the mutation from Logging.bootstrap to prevent foreign libraries messing with the logging system during application execution.

More detailed thoughts

Logging.bootstrap should have the ability to "lock" to the current _handler to prevent bad actor or poorly implemented foreign libraries suddenly changing the logging implementation on an application.

Tracing through OneGlobalLoggerExample.swift, everything - unless I have setup the code incorrectly - is actually logged to the StdoutLogger instance that was the result of the current _factory at the time the static logger was instantiated.

IMO, for the static logger case Logging.make shouldn't actually be creating implementations from the current _factory, which particularly for the case of static loggers which would require paying close attention to call and instantiation order. Easy to get wrong.

I feel it would be preferable that Logging.make simply create a proxy that resolves the actual LogHandler implementation at log time. Something like-

public protocol LogHandler {
    static func handler(for: String)
    ....
}

For the explicit passing case, this doesn't make sense however and perhaps there isn't a great way to unify these two use cases. Maybe Logging.make needs to be spilt into two-

  1. for the use case where the caller is responsible for bootstrapping the logging system (ie. is the application), a call to directly create a LogHandler implementation to be passed around.
  2. for the use case where the caller isn't responsible for bootstrapping the logging system (ie. is a library), they can create a proxy to specify who they are but they don't know what that actually means in terms of the underlying LogHandler implementation.

There is a distinction here between these two roles which the framework could make clearer-

  • if the caller is not responsible for bootstrapping the logging system (ie. a library) they shouldn't be relying on a global function to create LogHandler implementations as by definition they can't know if the logging system has been bootstrapped.
    • for the static logger case there should be an API to create a proxy that defers the determination of the LogHandler implementation to log time
    • for the explicit passing case, there should be an API to create a logger from a logger - the choice for a library is they create a static logger which is a proxy and pass that around or create further proxies from it or receive an explicit logger from someone who has bootstrapped the logging system and pass that around or create further direct implementations
  • if the caller is responsible for bootstrapping the logging system (ie. is the application), they have the knowledge to be able to safely create LogHandler implementations from a global function

#28

Logger delegates everything to the underlying handler, so basically a "dumb" proxy into the concrete logger implementation. the only logic it has is basic log level filtering (L34-36) which together with the fact that message is an @autoclosure gives us a performance edge: we dont need to evaluate the message when the log level is insufficient

note that the log level itself is managed by the underlying handler, which enables implementating config based logging libraries which were mentioned earlier in this thread. this is demonstrated in GlobalLoggerTest::test3 and TestLogger in the unit tests. TestLogging uses in-memory config for simplicity, but a real implementation of a config based logging library is likely to use config files external to the application. the idea is to allow "hot" changes of log levels for specific namespaces via external resources like config files when debugging an issue in prod or iow without needing to restart or redeploy the application. this is a very common pattern in large scale systems.


#29

to confirm, are you worried about racy initialization when using static loggers?

you are right the lack of such protection opens the door to mistakes. one idea we were playing with in earlier versions was to only ever allow a single bootstrap call. we eventually removed it from the proposal to be less opinionated / more flexible


(Johannes Weiss) #30

I think that's a good suggestion. I filed the question and after we reach consensus on the core APIs, we can add (through fresh Pitches/Proposals) features before we release 1.0.0 for the logging API.


(Johannes Weiss) #31

Very happy to discuss this but I think that's additive and if you don't mind, let's discuss it after the core issues. (filed though).

So that's fundamentally at odds with what others say (who feel adding one extra line let logger = Logging.make("program") is already too complicated.

I think we should provide a default so people don't need to know what a LogHandler is and how the log system works. The reason why I think it's okay without fully understanding it is that at any point in time you make add one line (Logging.bootstrap(MyBetterThanDefaultLogHandler.self)) to your program and the LogHandler is changed throughout the whole application, including any libraries.

Does that make sense?

I'm inclined to also punt this to 'after the core issues', I filed this issue too so we won't forget.

:+1:

Agreed!