Logging improvements.

[ileitch]

Hey all 👋

I'm new Vapor and loving it so far! My prior development experience is most recently iOS, but before that I was an SRE using Rails. I've discovered that logging in Vapor doesn't quite match my expectations based on my past experiences.

Example 1: Server

[ INFO ] GET /favicon.ico
[ ERROR ] Not Found

At the info log level this output is OK (if a little terse), but at the warning level and above it becomes useless since the error line provides no context.

Example 2: Queues

[ INFO ] Starting jobs worker (queue: tmdb)
[ INFO ] Dequeing Job:
[ INFO ] Dispatched queue job
[ INFO ] Dequeing Job:
[ INFO ] Dequeing Job:
[ INFO ] Dispatched queue job
[ INFO ] Dequeing Job:

This output at least tells me something happened, but otherwise it's mostly useless. I'll discuss log levels more below, but I think it's important to mention that this is the default output for Vapor in the development environment, and therefore what newcomers experience.

Vapor can of course log more information using the metadata mechanism, but at at least in ConsoleLogger that's restricted to the debug level. This behavior is contrary to my past experiences. For iOS we would log quite liberally at the info level, and include those logs in crash reports sent to Crashlytics. Things we'd log at this level included network activity, state machine transitions, events, etc. We logged everything necessary to help us track the users progress through the app to help in diagnosing the crash. In Rails we also used logging liberally.

We could try to define exactly the amount of information that each log level should include, but I think many people have their own preference, so while sensible defaults are great, it'd be great if we could accommodate everyone's personal preference.

Therefore I'd like to put forward some ideas. Please note that the examples provided below aren't serious API suggestions, they're just to convey the concepts.

1. Associate each metadata item with a log level

logger.info("Hello", metadata: [
    .info("job", name),
    .debug("payload", payload)
])

Rather than all metadata only being logged at the debug level, this gives us the ability to more finely control individual log line verbosity.

2. Define default metadata items, and allow their log level to be customized

Each subsystem (e.g queues, server, etc.) defines a default set of metadata items that are included on every log line output by that subsystem, even for custom lines added by users. For example the queues subsystem might contain:

struct MetadataItem {
    static var timestamp: Self {
        .init(name: "timestamp", value: { ... })
    }
    static var jobId: Self {
        .init(name: "job-id", value: { ... })
    }
    static var jobName: Self {
        .init(name: "job-name", value: { ... })
    }
    static var location: Self {
        .init(name: "location", value: { ... })
    }
}

Then calling logger.debug("Hello") would yield 2020-05-20 12:00:00 [ INFO ] Hello [job-name: "MyJob", job-id: 1234] (File.swift:42)

To accommodate personal preference, users would also be able to customize the default items output at each log level, e.g:

queues.logger.defaultMetadata.include([.timestamp, .jobName], for: [.critical, .error, .warning])
queues.logger.defaultMetadata.include([.timestamp, .jobName, .jobId], for: .info)
queues.logger.defaultMetadata.include(.all, for: [.debug, .trace])

3. Output more information by default at the info level

Since info is the default in development mode, I think it should be more informative to aid development efforts, whilst also being a more friendly experience for newcomers.

[gwynne]

Log levels for metadata! 😍

Item 1 (log levels for metadata) sounds absolutely awesome!!! 🤩❤️❤️❤️🤩 I expect there'd be design questions to be addressed, but the ability to signal the intended "verbosity" of any particular piece of metadata to the underlying LogHandler with something like this would be incredibly useful (especially given a handler built to make good use of it!).

Default metadata per subsystem

Item 2 I'm on the fence about - "default" metadata smells suspiciously like an unintended gateway to leaking metadata all over places it doesn't need to be, especially if any sensitive info ever gets included. Anything (such as a third-party package) can create its own Logger at any time and override the configured LogHandler via the init(label:factory:) initializer; there would never be any useful way to guarantee any such global defaults were correctly applied (or correctly not applied). There would also be potential implications for retain cycles, memory usage in general, increased overhead of copying metadata dictionaries between loggers... I definitely agree the framework could benefit from adding a bit more formal structure of this kind to subsystems, but I don't think this specific direction fits with the existing design as well as it would need to 😕

More info for info

Item 3 I'm even more conflicted about. It's true that info is a more typical verbosity "tipping point" in common usage than debug, But outside codebases ruled by Apple's rigorous coding standards, I haven't yet seen a single package (not even in Vapor!) that has any discipline or consistency about how it uses log levels. I see .debug getting used for every single log statement fairly often. The worst example I've seen was an author with, I don't know, a divine conviction that .error was the only level that made sense to use for control flow tracing, outputting around 1000 lines per second and completely impossible to shut off even in production.

I suggest that, rather than focus specifically on the info level, the framework should consider offering some guidelines, or recommendations, or suggestions, or hints, or treasure maps readable only when the moon is in the Seventh House and Jupiter aligns with Mars (... I'm dating myself now, aren't I... 😨). What I mean is , there should be something, even just in the README, that gives users somewhere to start, and/or something to refer back to. As far as I know, nothing of that kind exists now. I'm currently imagining something like a considered set of sample usages, with two or three examples per log level (and it doesn't have to take that specific form, of course). I think it could only help the ecosystem as a whole. It might well be that info ends up being considered the appropriate space for getting talkative with your logging 🙂, but I'd hate for us to end up pigeonholing ourselves out of making more sweeping improvements.

A few other suggestions

Some additional thoughts I had:

• Subsystems need a bit more formal structure. Probably not much, even something as simple as wrapping it in a trivial struct, in the style of Notification.Name, would make it easier to define "well-known" subsystem labels. Would also be great if the builtin LogHandlers in both swift-log itself and ConsoleKit had a bit better support for them, such as filtering.

• The StdioOutputStream wrapper used by StreamLogHandler should be modernized and made public so that other handlers can build on it.

• ConsoleKit's ConsoleLogger should allow configuring the ConsoleStyle of each log level independently at runtime, as well as the global visibility of metadata and logger labels (which are currently only visible at .debug and .trace respectively). Whether these should be runtime-mutable or "configure once at startup", I don't know.

[ileitch]

Item 2 I'm on the fence about - "default" metadata smells suspiciously like an unintended gateway to leaking metadata all over places it doesn't need to be, especially if any sensitive info ever gets included. Anything (such as a third-party package) can create its own Logger at any time and override the configured LogHandler via the init(label:factory:) initializer; there would never be any useful way to guarantee any such global defaults were correctly applied (or correctly not applied). There would also be potential implications for retain cycles, memory usage in general, increased overhead of copying metadata dictionaries between loggers... I definitely agree the framework could benefit from adding a bit more formal structure of this kind to subsystems, but I don't think this specific direction fits with the existing design as well as it would need to 😕

These are all valid concerns, but I think they could be addressed to some degree by the API design. Personally I'd rather have this flexibility and live with some of the potential consequences.

To add a bit more weight behind this idea, I think having the ability to opt in/out of certain items would also be good for developer productivity. Let's say the queues subsystem includes the job name and ID by default (which it does, though only in debug mode). I might also like to include those items on the log lines I implement myself, but if the subsystem does not expose those values publicly, I'd have to implement them myself (if possible) and hope I implement them correctly. Perhaps a better example would be choosing to include the call-site location next to SQL query log lines, which I've seen done even in production configurations. I'd much rather not have to implement the logic to format the call site if it already exists in the subsystem somewhere.

Item 3 I'm even more conflicted about. It's true that info is a more typical verbosity "tipping point" in common usage than debug, But outside codebases ruled by Apple's rigorous coding standards, I haven't yet seen a single package (not even in Vapor!) that has any discipline or consistency about how it uses log levels. I see .debug getting used for every single log statement fairly often. The worst example I've seen was an author with, I don't know, a divine conviction that .error was the only level that made sense to use for control flow tracing, outputting around 1000 lines per second and completely impossible to shut off even in production.

I don't think we need to go crazy with adding a ton of extra detail to info, but in the server and queue examples I provided, just a couple more details would be very helpful. I think the server logs could include the status code and perhaps response time, whereas the queue logs could include the job name, and perhaps also the queue name.

I think these are good examples of where just a little extra information can be very helpful, yet doesn't introduce too much noise. Keeping info too terse detracts from developer productivity in my opinion. Having to drop down into debug isn't ideal since I then also have to deal with a lot of extra noise. I think info should provide enough information so that I can reasonably understand the execution flow of my code in 95% of cases. Using debug should be the exception for when the issue isn't generally obvious.

[Jeehut]

Any updates on this? The metadata (especially timestamp) would be a very useful addition! Is there something planned here? @tanner0101 added it for Vapor 4, but we have Vapor 4 for quite a while now without this feature ...

[0xTim]

To add a few things to this:

• The SSWG recently released a log level guide for libraries. Vapor has moved most of it's code over to follow these rules, though there are definitely edge cases where we want to break these and cases where we should move the log level to debug.
• Metadata would definitely be awesome
• Timestamps should be off by default and configurable - ConsoleLogger is the default logger for Vapor and most log systems will append their own timestamps to the logs so we don't need to duplicate them. Though it would be useful to turn them on that don't need them
• You can always switch the logging backend out to something more complex

It's unlikely any of the core team will get a chance to look at this any time soon, we have a lot on our plate with async/await and other more pressing issues so hopefully someone from the community can pick this up!

[gwynne]

This was effectively implemented by #182