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.