[Discussion] Server Logging API

[johannesweiss]

@graskind

I remain unconvinced that custom logging levels are worth the complexity. Your example with the Vapor database system is a good one but I believe you can achieve the same thing in two slightly different ways depending on how you plan to use the logger:

• if you go for the explicitly passing the logger around model, I'd just add a logger[metadataKey: "subsystem"] = "com.vapor.database" and you'll later be able to filter out all database messages easily
• if you go for the 'one logger per sub-system' then you'd have the Vapor database layer create a logger with identifier com.vapor.database and again, the filtering should be rather straightforward.

Think that would work?

I do somewhat, but I have concerns about using the metadata in particularly this way - more on that below. I would almost always prefer to do "one logger per subsystem", but more than once in practice it's turned out that I have a lot of trouble separating out what logs belong to what subsystem, even with very well-isolated abstractions. In particular, really good abstraction layers are not something I tend to have during the early stages of a project's development - I find myself going back and changing how my logging is organized over and over and over.

Right, but that's not solved by custom log levels either, right?

@graskind

The biggest hurdle with the "one logger per subsystem" model, in my experience, is keeping the logger objects accessible to the contexts using them. Calling Logger("com.exmaple.foo") everywhere that wants that subsystem (even if the API supported using it this way, which I wouldn't want it to!) presupposes either extremely cheap initialization, a global cache (with all the myriad attendant issues of that ), or compile-time evaluation, none of which are desirable requirements. At the same time, passing Logger s around tends to demand certain compromises in design - vars or functions in global scope, objects that conform to a hypothetical ContainsContextualLogger protocol, ivars/methods with mostly repeated implementations in many different files and/or objects, and so on. Refactoring becomes increasingly messy. And I don't know if this has been brought up in this thread already, but there's also the question of preserving contextual metadata from one subsystem in a Logger that belongs to a "lower-level" subsystem - so now you need to be able to do Logger("com.example.bar", inheriting: fooLogger) , or carefully build your subsystems to have the needed context or not need to log it without losing the specificity, or otherwise have a LogContext (which I know I've seen mentioned somewhere in here).

Yes, these are all valid issues. I personally am the 'passing the logger around explicitly' kind of person which makes the contextual logging fairly straightforward and Loggers can be value types etc. But it does make it harder to have per sub-system logging messages. Sometimes you can use #file as a proxy for what sub-system it is but it's not great either. The thing is that I don't think there's a good answer for everybody, we just can't force everybody to pass loggers around explicitly nor can we tell people that that's not supported.

If you want to have both 'sub-system' loggers and contextual logging then I think the only way is to built the context separately and then pass it onto the logging methods manually (with added metadata: parameters to every log method, like @artemredkin was proposing up-thread). Or obviously MDC which propagates the contextual information through thread-locals but sub-system loggers + MDC + Dispatch == needs-manual-assistance propagating the context

@graskind

As unfortunately usual, I don't have a good suggestion for solutions to the issue, I'd need to spend some time tinkering. I just don't want it to pass unmentioned

I know, there's no perfect solutions here that work for every architecture and belief...

@graskind

johannesweiss:

graskind:

Logging configuration

[snip]

• 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"?

Yes, they are strongly ordered and if the log-level is at warn , the LogHandler won't even see any messages that are below warn . This was a deliberate decision so that we don't need to forward the @autoclosure to the existential LogHandler type. Why? Because currently @autoclosure will alloctate if the called function cannot be inlined. And you can never inline across an existential (because well the implementation is chosen at runtime...).

I've read over this several times and still can't quite work out in my head why the @autoclosure would need to be forwarded. I think I'm missing a piece somewhere in the flow of data . In fact, re-reading this again, I'm not quite clear on which thing you were saying was deliberate by design: "passing only the configured messages to the handler", or "having only one configured logging level rather than a set". Can you clarify?

Sure, at the moment in Swift, both @autoclosure and closure arguments (with non-nil contexts) will allocate (ie. call malloc). So if you have a ModuleA which defines func foo(_ body: () -> String) and you call it from ModuleB as

let a = "hello"
foo {
  return a
}

an allocation will happen when foo is called for the closure's context (the captured variables). @autoclosures are the same, they just are a nicer syntax for this. The only way to get around that is inlining. Ie. making it @inlinable func foo(_ body: () -> String). That way the compiler will (hopefully) inline foo's body into the caller and it's no longer actually building a closure.

That's why Logger is a struct and all its methods are inlineable: Within the (hopefully) inlined code we know if we need to produce the log message string (by evaluating the @autoclosure) or not. And only after having decided that we do need to log, we evaluate the @autoclosure and pass the result on as a String to the LogHandler. So with a bit of support from the inlining gods, we no longer need to allocate.

If we passed the @autoclosure straight through to the LogHandler, it can't inline that and we do actually need to allocate for the closure. And there's no way we can inline the LogHandler implementation into the caller because the LogHandler is selected at runtime.

Really, this should be addressed in the compiler and the closure context should be stack allocated (because the closure is non-escaping) but that hasn't been done AFAIK.

@graskind

johannesweiss:

There is however quite an easy workaround: Your log handler can accept setting log levels (and store that) but when asked about the log level it just always returns .trace . This way the LogHandler can see all messages and can optionally add some fancier stuff.

I like this - though in other logging systems I've seen, it's defined by API contract that a LogHandler always receives all log messages, regardless of level, and can decide what to do with them on that basis. I don't know how that would look for performance, but it has the virtue of both simplicity and consistency.

Agreed, but then every log message would be an allocation, if actually logged or not. That's unacceptable for a non-starter for now. I'd hope that this is fixed in Swift rather sooner than later but I think we need a solution before that. For more information, check this thread, especially the newer messages.

@graskind

johannesweiss:

graskind:

• Is there value in an additional field such as "subsystem" and/or "category" (as found in os_log() ) for providing (even) more control?

I believe that convention and logging meta-data is good enough here. So if everybody uses the "subsystem" key, it should work. We could also (later) add the strings as proper constants to the logging API.

This is one where I'm just not sure I agree. Well-known subscripts to an arbitrary metadata map are still stringly-typed data, and that level of flexibility is typically most useful to clients of an API, not the API itself. If the API goes to the trouble to define "well-known" metadata in the first place, it should make that metadata part of the API contract and provide explicit properties. This preserves the maximum amount of static type information, keeps the metadata namespace unambiguous, and makes it less likely that clients will accidentally miss the existence of the keys and end up pointlessly duplicating the functionality.

That being said, this is certainly something that would stand outside the scope of the first version/draft of the API - it deals much more in concrete implementations than protocols. I would say file an issue for this and address it later, but do address it.

I still think that it might open a kitchen sink of information that one or the other person needs and (totally contrary to my normal opinions) I think here stringly typed is okay. Why? Because everybody I've seen on the server-side analyses logs with textual tools anyway. I mean we teach Splunk how to parse the messages that we serialised costly on the other end. But I don't want to say 'no' to this but for this proposal at this stage I don't think we should do it. If this goes forward and we have gained experience, then I think we can pitch enhancements but at this point I feel it's too risky to design features for a system that nobody has used in production quite yet.

@graskind

johannesweiss:

graskind:

• Should this decision be left up to LogHandler s or be encapsulated by the Logger ?
• Is "current level" global, per- Logger , per- LogHandler , or something else?

it depends . There are so many different approaches to logging that this needs to be decided by the LogHandler s themselves. Maybe in the future one way of logging will 'win' and we can adjust this but currently this is deliberately left to the LogHandler .

On this one, I'm pretty sure I come down on the side of leaving it to the LogHandler , especially if we end up saying that handlers always receive all messages. I don't see a need to provide extra guidance from the API for it, all that could ever do is limit the API's capabilities.

yes

@graskind

johannesweiss:

graskind:

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.

If it covers the basic API I think it's worth mentioning. For example I'm thinking about (in a separate thread) asking the community if they like

logger.info("Hello World") and logger.error("bad") (as proposed so far)

or

logger.log(level: .info, "Hello World") and logger.log(level: .error, "bad")

better.

Well, I certainly can't speak for the community as a whole . But speaking for myself, I very much prefer the former (current) style as bother more "fluent" and more terse. Ultimately, I would say "provide both but visibly prefer the shorter form".

I do too but the same applies to me, can't speak for the community hence I'm considering asking (on a separate thread) if we should change. But that's really a small detail so maybe not now :).