[Discussion] Server Logging API

Server Proposals
1

SSWG Logging API

Introduction

Almost all production server software needs logging that works with a variety of packages. So, there have been a number of different ecosystems (e.g. Vapor, Kitura, Perfect, ...) that came up with their own solutions for logging, tracing, metrics, etc.
The SSWG however aims to provide a number of packages that can be shared across within the whole Swift on Server ecosystem so we need some amount of standardisation. Because different applications have different requirements on what logging should exactly do, we're proposing to establish a SSWG logging API that can be implemented by various logging backends (called LogHandler).
LogHandlers are responsible to format the log messages and to deliver them on. The delivery might simply go to stdout, might be saved to disk or a database, or might be sent off to another machine to aggregate logs for multiple services. The implementation of LogHandlers is out of scope of this proposal and also doesn't need to be standardised across all applications. What matters is a standard API libraries can use without needing to know where the log will end up eventually.

Motivation

As outlined above we should standardise on an API that if well adopted and applications should allow users to mix and match libraries from different vendors while still maintaining a consistent logging.
The aim is to support all widely used logging models such as:

  • one global logger, ie. one application-wise global that's always accessible
  • a scoped logger for example one per class/sub-system
  • a local logger that is always explicitly passed around where the logger itself can be a value type

There are also a number of features that most agreed we will need to support, most importantly:

  • log levels
  • attaching meta-data (such as a request ID) to the logger
  • being able to 'make up a logger out of thin air'; because we don't have one true way of dependency injection and it's better to log in a slightly different configuration than just reverting to print(...)

On top of the hard requirements the aim is to make the logging calls as fast as possible if nothing will be logged. If a log message is emitted, it will be mostly up to the LogHandlers to do so in a fast enough way. How fast 'fast enough' is depends on the requirements, some will optimise for never losing a log message and others might optimise for the lowest possible latency even if that might not guarantee log message delivery.

Proposed solution

The proposed solution is to have one struct Logger which has a supports a number of different methods to possibly emit a log message. Namely trace, debug, info, warning and error. To send a log message it's usually enough to

logger.info("hello there")

This now raises the question: Where does logger come from? To this question there is two answers: Either the environment (could be a global variable, could be a function parameter, could be a class property, ...) provides logger or if not, it is always possible to obtain a logger from the logging system itself (a.k.a. making up a logger out of thin air):

let logger = Logging.make("com.example.example-app")
logger.info("hi again")

To get the best logging experience and performance, it is advisable to use .make to pass Loggers around or store them in a global/instance variable rather than .makeing new Loggers whenever one needs to log a message.

Apart from knowing where one obtains a Logger from, it should be interesting to see what one can do with one:

public struct Logger {
    public var logLevel: LogLevel

    public func trace(_ message: @autoclosure () -> String, file: String = #file, function: String = #function, line: UInt = #line)
    
    public func debug(_ message: @autoclosure () -> String, file: String = #file, function: String = #function, line: UInt = #line)
    
    public func info(_ message: @autoclosure () -> String, file: String = #file, function: String = #function, line: UInt = #line)
    
    public func warn(_ message: @autoclosure () -> String, file: String = #file, function: String = #function, line: UInt = #line)
    
    public func error(_ message: @autoclosure () -> String, file: String = #file, function: String = #function, line: UInt = #line)
    
    public subscript(metadataKey metadataKey: String) -> String? { get set }
    
    public var metadata: LoggingMetadata? { get set }
}

I guess logLevel, trace, debug, info, warning and error are rather self-explanatory but the meta-data related members need some more explanation.

Detailed design

Logging meta-data

In production environments that are under heavy load it's often a great help (and many would say required) that certain meta-data can be attached to every log message. Instead of seeing

info: user 'Taylor' logged in
info: user 'Swift' logged in
warn: could not establish database connection: no route to host

where it might be unclear if the warning message belong to the session with user 'Taylor' or user 'Swift' or maybe to none of the above, the following would be much clearer:

info: user 'Taylor' logged in [request_UUID: 9D315532-FA5C-4E11-88E9-520C877F58B5]
info: user 'Swift' logged in [request_UUID: 35CC2687-CD1E-45A3-80B7-CCCE278797E6]
warn: could not establish database connection: no route to host [request_UUID: 9D315532-FA5C-4E11-88E9-520C877F58B5]

now it's fairly straightforward to identify that the database issue was in the request where we were dealing with user 'Talor' because the request ID matches. The question is: How can we decorate all our log messages with the 'request UUID' or other information that we may need to correlate the messages? The easy option is:

log.info("user \(userID) logged in [request_UUID: \(currentRequestUUID)]")

and similarly for all log messages. But it quickly becomes tedious appending [request_UUID: \(currentRequestUUID)] to every single log message. The other option is this:

logger[metadataKey: "request_UUID"] = currentRequestUUID

and from then on a simple

logger.info("user \(userID) logged in")

is enough because the logger has been decorated with the request UUID already and from now on carries this information around.

Custom LogHandlers

Now, let's put the logging meta-data aside and focus on the how we can create and configure a custom logging backend. As seen before, Logging.make is what gives us a fresh logger but that raises the question what kind of logging backend will I actually get when calling Logging.make? The answer: It's configurable per application. The application -- likely in its main function -- sets up the logging backend it wishes the whole application to use. Libraries should never change the logging implementation as that should owned by the application. Setting up the LogHandler to be used is straightforward:

Logging.bootstrap(MyFavouriteLoggingImplementation.init)

This instructs the Logging system to install MyFavouriteLoggingImplementation as the LogHandler to use. This should only be done once at the start of day and is usually left alone thereafter.

Next we should discuss how one would implement MyFavouriteLoggingImplementation. It's enough to conform to the following protocol:

public protocol LogHandler {
    func log(level: LogLevel, message: String, file: String, function: String, line: UInt)
    
    var logLevel: LogLevel { get set }
    
    subscript(metadataKey metadataKey: String) -> String? { get set }
    
    var metadata: [String: String]? { get set } 
}

log and logLevel need to always be implemented. Logging meta-data can be implemented by always returning nil and ignoring all metadata that is being attached to a logger but it is highly recommended to store the metadata in an appropriate way with the LogHandler and emit it with all log messages.

The implementation of the log function itself is rather straightforward: If log is invoked, Logger itself already decided that given the current logLevel, message should be logged. In other words, LogHandler does not even need to compare level to the currently configured level. That makes the shortest possible LogHandler implementation really quite short:

public struct ShortestPossibleLogHandler: LogHandler {
    public var logLevel: LogLevel = .info 
    
    public init(_ id: String) {}

    public func log(level: LogLevel, message: String, file: String, function: String, line: UInt) {
        print(message)
    }
    
    public subscript(metadataKey metadataKey: String) -> String? {
        // ignore all metadata, not recommended
        get { return nil }
        set { }
    }
    
    public var metadata: [String: String] {
        // ignore all metadata, not recommended
        get { return nil }
        set { }
    }
}

which can be installed using

Logging.bootstrap(ShortestPossibleLogHandler.init)

Supported logging models

This API intends to support a number programming models:

  1. explicit logger passing (see ExplicitLoggerPassingExample.swift)
  2. one global logger (see OneGlobalLoggerExample.swift)
  3. one logger per sub-system (see LoggerPerSubsystemExample.swift)

Because there are fundamental differences with those models it is not mandated whether the LogHandler holds the logging configuration (log level and meta-data) as a value or as a reference. Both systems make sense and it depends on the architecture of the application and the requirements to decide what is more appropriate.

Certain systems will also want to store the logging meta-data in a thread/queue-local variable, some may even want try to automatically forward the meta-data across thread switches together with the control flow. In the Java-world this model is called MDC, your mileage in Swift may vary and again hugely depends on the architecture of the system.

I believe designing a MDC (mapped diagnostic context) solution is out of scope for this proposal but the proposed API can work with such a system (see examples).

Seeking feedback

Feedback that would really be great is:

  • if anything, what does this proposal not cover that you will definitely need
  • if anything, what could we remove from this and still be happy?
  • API-wise: what do you like, what don't you like?

Open Questions

A couple of questions come to mind:

  • Currently, attaching metadata to a logger is done through subscript(metadataKey metadataKey: String) -> String? { get set }. In code it would be logger[metadataKey: "request_uuid"] = "...", is this a good use of a subscript?
  • Should the logging metadata values be String?
  • Should this library include an MDC API? Should it be a separate module? or a separate library? SLF4J which is the moral equivalent of this API in the Java ecosystem does include one.
13 Likes
2

Needless to say that as soon as this is available to us the server logging API should incorporate all of the exciting performance wins that will become available using custom string interpolation and compile-time interpretation of that.

Our API will likely always be wider than osLog because of the extra requirements but we will still be able to leverage performance gains by the new compiler/language support :raised_hands:.

2 Likes
3

Questions for clarification:

  • Are "Log", "Logging", and "Logger" distinct types or typos? Why do API names jump between using these three words seemingly randomly?
  • Does "Log", "Logging", and/or "Logger" conform to "LogHandler". If not, why not?

Overall feedback on the API:

This design seems to deviate pervasively from sometimes basic Swift design precedents, and it does not appear to justify those deviations. For example:

  • Why is initializing a logger spelled as a static function make and not as an initializer?

  • Why are subsidiary types such as LogLevel and LoggingMetadata (which, as per above, why aren't these both Logging or Log?) not nested types as per the example of Int.Words, Mirror.DisplayStyle, String.Index, Unicode.Scalar, and others?

  • Why does the protocol-with-global-default pattern here deviate from the precedent of RandomNumberGenerator, with the protocol named Log and the default named DefaultLog?

  • Why does using a specific logger not follow the pattern of print(_:to:), with the global logger as the default argument for to:, instead requiring users to find some way to spell the global logger? Critically, why is the "currency" (i.e., go-to) function not called log?

From the user perspective, and with due respect for principles of progressive disclosure, I would propose that the most basic API should look like this:

// Log a message to the default logger, with the default level
log("Hello, world!")

// Log a warning or error to the default logger
log(.warning, "Hello, warning!")
log(.error, "Hello, error!")

// Log a message to the default logger, with the default level,
// with custom source location
log("Hello, world!", file: "hello.swift", function: "", line: 2)

// Log a message to a custom logger, with the default level
var customLogger = CustomLogger("com.example")
log(to: &customLogger, "Hello, custom world!")

// Log a warning or error to a custom logger
log(.warning, to: &customLogger, "Hello, custom warning!")
log(.error, to: &customLogger, "Hello, custom error!")

// Append some metadata
customLogger.metadata["world"] = "hello"

// (Incidentally, why does the proposed API have a distinct subscript
// to access metadata keys and values *and* a publicly accessible
// member `metadata` that's a dictionary?)

Once we have a consensus on how use sites should look, the rest of the design can be derived on that basis.

10 Likes
4

First, thanks for moving this API forward.

I have some concerns with the proposed API:

  • There should be an easy & quick way to access a shared Logger instance without needing to make one. The API should include one and should be the default. Maybe something like Logger.default.info("Starting process...") or even better, using static methods Logger.info("Starting process...").
  • If I have understood correctly, it seems that with Logging.bootstrap() you can only attach one LogHandler. As with the Python logging API, I think we should make very easy to attach or detach any number of handlers to the logging system. Something like Logger.attach(handler:) and Logger.detach(handlerIdentifier:).
  • Each handler and logger should include a unique identifier. It would be great if using the default Logger, implies sending the messages with the identifier or name of the module, but I don't know if that's currently possible.
  • The existence of Logging and Logger is a bit confusing, I rather prefer to only expose a Logger struct and a Logger.Handler protocol.
  • Logger.warn() should be Logger.warning().
  • The LogHandlers should receive the identifier of the Logger being used, so we could filter messages emitted from some given subsystem or module.
1 Like
5

Thanks for the feedback, let me address them one-by-one

No, they are distinct and I'm obviously totally open to change the names or add clarification:

  • Log: I can't find this anywhere
  • Logging is the logging system itself, the one where you get Loggers from and the one where you register your LogHandler
  • Logger is the type that you invoke info, warning, error, etc on. It's the type that users would interface with

You would ask the logging system (Logging) to make you a logger (Logger) emitting its messages to a logging backend LogHandler. In most cases, the main function will choose a LogHandler, install this into the Logging system. Libraries and other parts of the program will never interface with a LogHandler, they will just ask the Logging system for a Logger if they don't get handed one from their execution context.

  • what is Log?
  • no, neither Logging, nor Logger conforms to LogHandler. Logger holds a LogHandler and Logging creates Loggers.

That's a fair enough suggestion, happy to take it if others feel similarly.

There is no global default. There is a very barebones LogHandler that is installed if you forget to choose one (StdoutLogHandler). A server application will likely have opinions about the logging system they want to use. They will need to create their own LogHandler and make the format match their Splunk/Kibana/... configuration so it can later on be parsed by those systems.

I'd say most serious server applications will have metadata attached to the logger itself. If you don't attach a request ID for example in many systems you might just as well not log at all. So I think

logger.info("hello")

just looks and feels better than

log(.info, "hello", &logger)

but obviously that's subjective. Also we would not hog a global free function (log).

Is there such a thing as a 'default log level'? And again, we likely need some metadata so people should re-use loggers if possible. It should always be easier to use a logger that may already be available than some default logger otherwise attaching the correct meta-data is very hard.

Even if people do the moral equivalent of what you write above which would be

Logging.make("com.myapp.MyComponent").info("Hello World")

then at the very least we have some component. Remember that in server software you often want to configure a different log level per request (say you do every 10,000th request at .trace level) or per subsystem (if something went wrong with the com.myapp.MyComponent component you want to log that component at say the .debug level and everything else at .warning). But obviously many requests and components are active in the same process concurrently.

3 Likes
6

Thanks very much for your thorough feedback!

I think I disagree here. If there's a default logger available, everybody will use it because we're lazy. But I do understand that in certain places this just what people want. I thought that we cater enough towards that crowd by supporting putting a single global variable

internal let logger = Logging.make("com.cool-library.TheBestLibrary")

in the TheBestLibrary. Then everywhere in TheBestLibrary you can just write

logger.info("hello")

But at the very least you need to reveal 'who you are'. Is this one extra line per module really such a big deal?

You did understand that correctly. If you really want multiple, why wouldn't you install a MultiLogHandler that would allow you to attach and detach handlers? I deliberately didn't want to design for 'all eventualities' but have an API expressive enough that you can get there if you need to.

Agreed, every logger should have an identifier but I'd like not to have a default logger if possible. AFAIK we can currently only get #function, #file, #line, #column and #dsohandle. #dsohandle in most SwiftPM applications will be the same across the whole executable (including all libraries). But if getting the current "scope's" name (ie. current type if any/module/...) were possible I'd also be in favour of using it.

Yes, I should have made a better job explaining that. Logger is the logger you call your log methods like info, warning and error on. Logging is the logging system where you obtain loggers from. Very happy to rename if anyone has good suggestions. Previously I had it down as LoggingAPI but that's not too nice, LoggingSystem would maybe be more clear but it a bit long. On the other hand, apart from the initialisation in the main function, it's only ever used to create new loggers.

Cool, happy with that, filed.

Oh sorry, yes I forgot to add that to the protocol, filed.

3 Likes
7

I do not want to hijack this thread, nor do I intend to ruin its success. I've seen quite a few logging approaches in Swift over the past few years and I also stumbled into few corners where I wished we had more flexibility on how we can obtain logs.

By the end of the day logging is just another way of printing a message to some sort of destination stream. That makes me wonder of we potentially could improve the Streaming API in the stdlib and either generalize print for logging, or build a standalone API on top of the improvements.

Here is one thread which I wish we could pursue as part of this discussion (if that's a reasonable thing to do):

2 Likes
8

Really good start. That said, I really encourage us to stay open minded and to challenge our core assumptions on what the ergonomics of a best-in-class logging API would look like for Swift. In other words, we have the ability and the responsibility to break away from the standards defined by other languages that lack expressiveness (like Java) where it makes sense to do so.

1 Like
9

I think that's exactly the right spirit. I'm not claiming this being superior to anything else, it's just the best we could come up with so far given the constraints.

10

I like the overall design very much. I also think though that it would be beneficial to have some kind of MultiLogHandler as you called it shipping by default. I guess that many developers want to use multiple logging platforms, which could each provide their own handlers.
Of course this could be done by any developer after the fact, but having one 1st party solution might be beneficial.

Another design I could imagine could work like NIO's channel handlers. Provide a pipeline for log handlers, where you can attach and detach as many and in whatever order you like. (I would actually prefer this to the one MultiLogHandler design)

3 Likes
11

I know it's sometimes considered an anti-pattern to use nested declarations as a sort of namespace, but perhaps we can have something like this?

/// Renaming of `LogHandler`
public protocol LogMessageHandler { ... }

public enum LoggingSystem {
    public struct Logger { ... }

    public struct Configuration {
        let handler: LogMessageHandler
        let metadata: ?? ?? // Bikeshed?
        let minLogLevel: ?? // Bikeshed?

        // pseudo until discussion on metadata & log level API
        public init(metadata = [], minLogLevel = .trace, handler = StdoutLogHandler)
    }

    public static bootstrap(with config: Configuration)
}

// usage
let configuration = LoggingSystem.Configuration(handler: MyCustomHandler())
LoggingSystem.bootstrap(with: configuration)
let logger = LoggingSystem.Logger("com.myapp.MyComponent")
logger.info("Running startup...")
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.

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.
1 Like
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

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.

6 Likes
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

4 Likes
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.

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

1 Like
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.