Improve debug logging

[JoelSpeed]

This PR intends to improve debug logging throughout the Faros codebase.

It introduces the logr framework and klog logging to allow more structured and levelled logging throughout the codebase.

I've also changed the logging so that it should log by default to stdout and only log to stderr for actual errors or if --logtostderr=true is passed CC @sebastianroesch

I've built an image which I'm going to test internally quay.io/pusher/faros:pull-114

This is pretty much exclusively conversion at the moment and doesn't actually add that much in the way of logging, but I think we need to work out what extra logs we want

Fixes #122 (?)

[JoelSpeed]

/build docker

[JoelSpeed]

/build docker

[JoelSpeed]

/build docker

[JoelSpeed]

/build docker

[JoelSpeed]

/retest

[JoelSpeed]

/build docker

[JoelSpeed]

/build docker

[JoelSpeed]

/build docker

[JoelSpeed]

/build docker

[JoelSpeed]

This is kind of annoying that it is at the V(1) level as V(2) (IMO) should be a reasonable default, but this makes things rather noisy

https://github.com/kubernetes-sigs/controller-runtime/blob/856708d78b479900b9d17f98f7f59a2f074fbc35/pkg/internal/controller/controller.go#L231

[mthssdrbrg]

Yay, logging! Looks reasonable at first glance. We should decide on a style for the fields, as they're now a mix of lowercase (maybe snake_case?) and CamelCase. Personally I prefer snake_case.

[sebastianrosch]

Awesome! I tested the build and it definitely fixes #122. I noticed that several logs appear multiple times, even though they should be logged only once, like:

I0424 09:41:24.325716       1 main.go:99] manager "level"=0 "msg"="Registering Components."
I0424 09:41:24.325716       1 main.go:99] manager "level"=0 "msg"="Registering Components."

I also noticed that --v=0 logs almost nothing while --v=1 is already spamming quite a bit. I would suggest we have one level that is similar to the current behavior and logs errors and normal operation, like checkout, without spamming. What do you think?

[JoelSpeed]

I've also noticed the spamming, though it is mostly out of our control (being inside controller-runtime).

I've been following the community guidelines on levels where they just have a 0 and a 1 level, which is kind of annoying, short of forking or proposing they follow the same guidelines I haven't worked out how we can be less spammy right now

[JoelSpeed]

@mthssdrbrg @sebastianroesch I've just added b047eac which offsets all controller-runtime logs by 3 levels, so the logs that were v=0 from CR become v=3 and the logs that were v=1 become v=4, this aligns their debug logging with our debug logging so should make reconciles quieter and gives us better control over what is printed at each of the lower levels

Not sure I 100% like this though so let me know what you think

[JoelSpeed]

/build docker

[JoelSpeed]

/build docker

[wonderhoss]

I really like the new structure in general, thanks @JoelSpeed for all the yak shaving involved.

One observation:
I feel that wherever we have a log line akin to Starting controllers..., we should also always have a corresponding like at the same severity that says All controllers started.
So, if we log the beginning of an activity, we also log when the activity is completed so that it becomes easier to reason about the execution flow just from the logs.

[JoelSpeed]

/build docker

[JoelSpeed]

@sebastianroesch FYI I've fixed the duplicate logging issue in my last push

I feel that wherever we have a log line akin to Starting controllers..., we should also always have a corresponding like at the same severity that says All controllers started.

@gargath in general I agree with you and for the most part in Faros we have that, however, that particular example that you have I can do very little about unfortunately. We post this message and then call mgr.Start(...) which blocks until a SIGTERM, so there's no easy was I can add extra logging there. Though that said, controller-runtime does include a bunch of logs about starting the controllers and would show that we have finished starting up

[JoelSpeed]

/retest

[JoelSpeed]

@mthssdrbrg Good spot on those inconsistencies, have fixed