Improve logging

[DanielVoogsgerd]

Currently, we default to debug/trace level logging inside the containers. I suggest we default to either > info or > warn, and make it so we can pass the debug level for the containers to branectl start.

Additionally, pretty colours from the rust logger are lost because it is not run in a tty. Even though docker logs does support coloured logging. There are two fixes for this. Set tty: true in the docker-compose files. This will make the binary think it is running on a tty and print its pretty colours. Alternatively, we can make this configurable as well, where a flag/env var during branectl start forces the logger to use colours.

[Lut99]

Good points! I think that the logging library supports fixing colours to always emit even if not running on a TTY (or else I can add it xD). Might make it easier in case you want to make it dynamic with a flag or only in the containers.

I once defaulted to --debug because everytime I needed the logs for bugfixing it turned out I needed the debug level info :P Plus, the only way to change it currently is to export the embedded compose file in branectl, change the flag, and then supply it everytime branectl runs. But yeah for production Brane INFO should be sufficient.

Also, I'm not sure that trace level is intended behaviour. I remember being surprised that bollard (I think it was) seems to sneak in TRACE-logs even though you tell my library it should only do debug and up. I'll double-check whether that's a bug on my end or whether bollard itself has some ideas about what level of tracing it should be at.

[DanielVoogsgerd]

Also, I'm not sure that trace level is intended behaviour. I remember being surprised that bollard (I think it was) seems to sneak in TRACE-logs even though you tell my library it should only do debug and up. I'll double-check whether that's a bug on my end or whether bollard itself has some ideas about what level of tracing it should be at.

I am seeing mainly the h2 crate emitting a lot of trace level info. What might help (a lot) is moving from the log crate to the tracing crate. It is an amazing crate from the tokio project, pretty compatible with the logging crate and more useful in async context such as a lot of the projects in Brane. It also supports pretty finegrained control of what is allowed to log at what log level. So you can specify that you want only trace logs from your main crate or dependency x, while keeping the rest at the default level.

I can recommend either the docs, or the stream from JonHoo on the topic.

P.S. The JonHoo streams are long, however they might be the most insightful content on Rust (Besides the book) available.

[Lut99]

tracing looks good! I'm not entirely sure yet how we'd use these spans though. I initially thought you'd use them to contextualize the work done so you can group log messages together by event occurring; but then I read they aren't really meant to span .await points (pun intended)... Or is that only for profiling, and it's fine for logging?

Anyway, I was recently thinking about a crate like this in another project xD so I can give it a test-drive there and see what is necessary to make the logs more useful.

[DanielVoogsgerd]

Ah no, as far as I know it is mainly a problem when using the Span::enter method. The guard from Span::enter should not be held across await points.

But I find using guard by hand to be a bit of an anti-pattern in most cases anyway. I prefer span::in_scope which takes a closure that enters at the start en drops the guard at the end.

Alternatively, I often use tracing::instrument which you can just use to annotate a function after which is automatically and transparently wrapped in a span.

Just a word of caution, span might come across at times as something that you want to slap onto anything, and while this is fun the first day or two, it gets old really quickly once you basically have a stacktrace in each logline.

[Lut99]

Haha I see, that makes sense xD Thanks for the headsup.

But alright, if tracing::instrument has no problem with await that's perfect then. I'll take a look at it :)