Slightly better default formatting for logs

[Mordil]

I know that this opens the floodgates of expanding the formatting capabilities of the basic dumb "out of the box" log handler this package ships with... but how do we feel providing a little better experience?

This would make debugging using SwiftLog in packages such as RediStack much easier as it wouldn't necessitate creating a custom formatter or pulling in a dependency just for development

Desired output

2020-09-18T22:51:14-0700 trace RediStack.RedisConnection : connection created
    rdstk_conn_id=AF0DFDB1-1C6F-43A4-B8C1-6AA09E84C363
2020-09-18T22:51:14-0700 trace RediStack.RedisConnection : received subscribe request
    rdstk_conn_id=AF0DFDB1-1C6F-43A4-B8C1-6AA09E84C363
2020-09-18T22:51:14-0700 trace RediStack.RedisConnection : adding subscription
    rdstk_ps_target=Channels 'multi_channel_test'
    rdstk_conn_id=AF0DFDB1-1C6F-43A4-B8C1-6AA09E84C363
2020-09-18T22:51:14-0700 debug RediStack.RedisConnection : not in pubsub mode, moving to pubsub mode
    rdstk_conn_id=AF0DFDB1-1C6F-43A4-B8C1-6AA09E84C363
2020-09-18T22:51:14-0700 trace RediStack.RedisConnection : handler added, adding subscription
    rdstk_conn_id=AF0DFDB1-1C6F-43A4-B8C1-6AA09E84C363
2020-09-18T22:51:14-0700 trace RediStack.RedisConnection : successfully entered pubsub mode
    rdstk_conn_id=AF0DFDB1-1C6F-43A4-B8C1-6AA09E84C363 

Current output

2020-09-18T22:51:14-0700 trace RediStack.RedisConnection : rdstk_conn_id=AF0DFDB1-1C6F-43A4-B8C1-6AA09E84C363 connection created
2020-09-18T22:51:14-0700 trace RediStack.RedisConnection : rdstk_conn_id=AF0DFDB1-1C6F-43A4-B8C1-6AA09E84C363 received subscribe request
2020-09-18T22:51:14-0700 trace RediStack.RedisConnection : rdstk_ps_target=Channels 'multi_channel_test' rdstk_conn_id=AF0DFDB1-1C6F-43A4-B8C1-6AA09E84C363 adding subscription
2020-09-18T22:51:14-0700 debug RediStack.RedisConnection : rdstk_conn_id=AF0DFDB1-1C6F-43A4-B8C1-6AA09E84C363 not in pubsub mode, moving to pubsub mode
2020-09-18T22:51:14-0700 trace RediStack.RedisConnection : rdstk_conn_id=AF0DFDB1-1C6F-43A4-B8C1-6AA09E84C363 handler added, adding subscription
2020-09-18T22:51:14-0700 trace RediStack.RedisConnection : rdstk_conn_id=AF0DFDB1-1C6F-43A4-B8C1-6AA09E84C363 successfully entered pubsub mode

[ktoso]

Hmmm that's a tricky policy decision to be honest...

I absolutely agreed that the default formatting becomes completely unreadable when a lot of metadata is used (I do so myself in all projects I work on, including apple/swift-cluster-membership where it shows a lot since every log statement carries tons of information about the membership state and protocol internals...

To that end, it even comes with it's own formatter to be usable in the example apps without going insane: swift-cluster-membership/.../Sources/SWIM/Utils/_PrettyLog.swift.

That one does a bit of pretty formatting with nested things and prefixes metadata with // to allow colorizing output more easily in iterm etc.

So the problem definitely is real and I agree with the general idea 🤔 "but..." 😉

---

I am worried if the solution should be to by default go multi-line in this formatter... Going multi-line is nice for development time, but terrible for log aggregation - aggregators usually assume 1 line = 1 log statement. It's a non trivial extra step to configure some of them to understand trailing stuff...

So... what should we do here?

I think it's a bit risky to make the default go multi-line to be honest.
It would be best if we shipped some PrettyLog and people do #if DEBUG PrettyLog.bootstrap() or something like that, but I would really want to put proper log handlers outside of this package -- it always was meant to be only API, and the fact this contains any handler already is root to some issues...

[Mordil]

From the PR:

@ktoso Hmmm that's a tricky policy decision to be honest...

I absolutely agreed that the default formatting becomes completely unreadable when a lot of metadata is used (I do so myself in all projects I work on, including apple/swift-cluster-membership where it shows a lot since every log statement carries tons of information about the membership state and protocol internals...

To that end, it even comes with it's own formatter to be usable in the example apps without going insane: swift-cluster-membership/.../Sources/SWIM/Utils/_PrettyLog.swift.

So the problem definitely is real and I agree with the general idea.

I am worried if the solution should be to by default go multi-line in this formatter... Going multi-line is nice for development time, but terrible for log aggregation - aggregators usually assume 1 line = 1 log statement. It's a non trivial extra step to configure some of them to understand trailing stuff...

So... what should we do here?

I think it's a bit risky to make the default go multi-line to be honest.
It would be best if we shipped some PrettyLog and people do #if DEBUG PrettyLog.bootstrap() or something like that, but I would really want to put proper log handlers outside of this package -- it always was meant to be only API, and the fact this contains any handler already is root to some issues...

Yes, I definitely agree. I knew that opening this issue & PR would be a can of worms for us to deal with. It's also the exact situation that Johannes wanted to avoid by not shipping a Logger & Log Handler ready out of the box.

I'm just not sure what the best solution is, because as soon as we allow any configuration, it's going to be harder and harder to push back against further customization or the ecosystem just building off of the default as it is.

Maybe the unfortunate reality is that we push package authors to pull in a dependency just for development - the state of the world is much better that SwiftPM will only fetch those when needed by the end-user dependency graph

[ktoso]

Input from @yim-lee @Lukasa @glbrntt @tomerd also welcome.

Really what we need is getting together and making a "proper good" log handler... otherwise we'll never get out of this adding features into swift-log 🤔

[ktoso]

Another approach would be to "bite the bullet" and make swift-log contain a great configurable but only stdout handler... other like file stuff we'd leave to external...? Slippery slope but something to consider

[Lukasa]

I strongly vote for not extending the current log handler. While it's ugly for development (unquestionably), it falls into the pit of success by being almost perfect for automated tooling. In general, the SSWG ecosystem leans a bit harder towards the "develop at scale" story, and that includes having defaults that work well for automated tooling even if that makes them a bit less good for the manual case. In general my opinion is that logging is for robots to consume, and for humans to interrogate only after those logs are processed.

If a tool wants to produce nice, human-readable output it should do that. In general that also doesn't justify dirtying up stdout with logs. If the tool is a CLI tool it will either be producing structured output for use in pipelines, or it'll be producing textual output for clean human consumption: logs are neither. It would be better in those cases for the tool to find another way to log (e.g. by logging to file), freeing up stdout for the productive output of the tool.

[tomerd]

Really what we need is getting together and making a "proper good" log handler... otherwise we'll never get out of this adding features into swift-log

I strongly vote for not extending the current log handler. While it's ugly for development (unquestionably), it falls into the pit of success by being almost perfect for automated tooling

imo, a good course of action would be to get together to build human friendly log-handler, or even a robust configurable log-handler that can deal with formatting along side other often-requested features

Maybe the unfortunate reality is that we push package authors to pull in a dependency just for development - the state of the world is much better that SwiftPM will only fetch those when needed by the end-user dependency graph

right, I think with conditional target dependencies library authors can bring in this awesome-log-handler (temp name) into their test targets, which seems fine? its not uncommon to have such "test dependencies"

[glbrntt]

I'm against making the current log handler configurable for the same reasons others have pointed out above.

I'm also okay with it as-is, it's not perfect but it's good enough out of the box most of the time. For projects where I've needed something different/better for I wrote my which has actually proven to be very valuable.

@tomerd has pointed at exactly the future I'd like to see here: SPM supporting testing and runtime only dependencies which allow for library developers to create and use log handlers which exactly suit their needs without polluting their consumers dependency graphs, be they formatting log handlers, capturing log handlers and so on.

[ktoso]

Seems like we have agreement: we need a separate "nice" human readable log handler.

Would you like to kick off such repo and we can collaborate on it @Mordil ?
Maybe swift-human-readable-log if that's the main thing we want to address with it, or let's start work on a "proper very configurable" backend if that's something you're up to?

[Mordil]

This is all completely understandable, and what I figured would be the outcome.

I'd love to kick it off and drive it, I've been thinking about it a good while, but right now I have too many pieces moving that I need to wrap up.

If we still don't have a point-person by around the US Holiday season, I'll try whipping up a quick proof-of-concept package while I'm holiday

[ktoso]

Maybe if you can't find the time to maintain it yourself you could try pitching the idea in the forums and see if someone would be willing to help? It's usually tricky to get someone fired up about "other person's idea" like that, but perhaps in this case there might be enough interest from someone if we clearly signal there's no intent of making it happen in swift-log itself so no reason to "wait for it"?

[Mordil]

@ktoso This is true. I'll find some time to write a pitch on the forums