refactor: use go-logr/logr with log/slog backend #1791

bakunowski · 2024-04-07T14:02:55Z

Addresses #1419

This PR standardises on the go-logr/logr interface with log/slog as the actual logging implementation.

Level names

There's a little bit of logic on top of the globalLogger to achieve clearer level field names in log messages. By default logr negates the V() for slog, effectively achieving:

logr	slog
V(1)	-1
V(2)	-2
...	...
V(4)	-4 (DEBUG)

In practice, this means that the following logs:

log.Info("0")
log.V(1).Info("", "slog-level", "1")
log.V(2).Info("", "slog-level", "2")
log.V(3).Info("", "slog-level", "3")
log.V(4).Info("", "slog-level", "4")

result in the following log output:

time=2006-01-02T15:04:05.000-07:00 level=INFO msg=0
time=2006-01-02T15:04:05.000-07:00 level=DEBUG+3 msg="" slog-level=1
time=2006-01-02T15:04:05.000-07:00 level=DEBUG+2 msg="" slog-level=2
time=2006-01-02T15:04:05.000-07:00 level=DEBUG+1 msg="" slog-level=3
time=2006-01-02T15:04:05.000-07:00 level=DEBUG msg="" slog-level=4

Using ReplaceAttr from slog.HandlerOptions allows us to modify it, getting rid of the +{number} bit from level field. The same logs achieve the following output:

time=2006-01-02T15:04:05.000-07:00 level=INFO msg=0
time=2006-01-02T15:04:05.000-07:00 level=DEBUG msg="" slog-level=1
time=2006-01-02T15:04:05.000-07:00 level=TRACE msg="" slog-level=2
time=2006-01-02T15:04:05.000-07:00 level=TRACE msg="" slog-level=3
time=2006-01-02T15:04:05.000-07:00 level=TRACE msg="" slog-level=4

Currently the lowest defined level is LevelTrace at V(2) or slog.Level(-2), meaning that any logs with a higher logr level will never be shown.

Warning level

Since logr maps to slog.Level() by negating the V() field, it's impossible to log at warning level. I've added PR comments to highlight instances of log.Warn and tried to replace them with what made sense to me.

netlify · 2024-04-07T14:03:13Z

✅ Deploy Preview for docs-kargo-akuity-io ready!

Name	Link
🔨 Latest commit	`e02a73a`
🔍 Latest deploy log	https://app.netlify.com/sites/docs-kargo-akuity-io/deploys/66200ef11173490008ea233f
😎 Deploy Preview	https://deploy-preview-1791.kargo.akuity.io
📱 Preview on mobile	Toggle QR Code... Use your smartphone camera to open QR code link.

To edit notification comments on pull requests, go to your Netlify site configuration.

cmd/controlplane/api.go

cmd/controlplane/controller.go

internal/controller/stages/stages.go

internal/controller/warehouses/git.go

internal/credentials/credentials.go

cmd/controlplane/api.go

cmd/controlplane/controller.go

cmd/controlplane/garbage_collector.go

cmd/controlplane/management_controller.go

cmd/controlplane/webhooks.go

krancour · 2024-04-09T01:03:41Z

internal/api/kubernetes/client.go

@@ -578,15 +578,15 @@ func GetRestConfig(ctx context.Context, path string) (*rest.Config, error) {
 // is empty, but will issue a warning that we can suppress by checking for
 // that condition ourselves and calling rest.InClusterConfig() directly.
 if path == "" {
- logger.Debug("loading in-cluster REST config")
+ logger.V(1).Info("loading in-cluster REST config")


I feel uncertain about anywhere where we see something like logger.V(1). Doesn't the call to V() change the verbosity level? Except for in the startup logs, (as mentioned here) we want to use the level specified by whoever installed Kargo. i.e. If obtained from logging.LoggerFromContext, it should already be configured to the correct verbosity.

As far as I understand it, based on the docs here logr doesn't provide named levels (and therefore an API like logr.Debug). So, logr.Info is equivalent to logr.V(0).Info at verbosity level 0.

If we, for example, wanted to map logr levels directly to slog.Level as defined here, the Info level would remain as logr.Info or logr.V(0).Info and Debug level would become logr.V(4).Info, since logr negates the verbosity level to match slog docs.

Because we customise names of the level keys here, logr.V(1).Info() is equivalent to a Debug log, with verbosity 1.

The call to V() does change the verbosity level of that particular log, but has nothing to do with slog.HandlerOptions.Level. If slog.HandlerOptions.Level is set to LevelInfo (slog.Level(0)), logs with V(1) effectively won't be printed.

Sorry, I'm finding this quite tricky to explain well. I tried to give some examples under the "Level names" heading in the PR description. Let me know if this message helps at all, or just makes everything more confusing.

🤦‍♂️ You're right. Although I'm comfortable with the notion of an abstraction over the underlying logger (mainly from my Java days), having not used logr before, I wasn't at all prepared for how wildly different the interface is from what I am accustomed to. My initial reaction is that needing to remember numeric levels as I code seems painful in comparison to .Debug() or .Warn(). Let me cozy up with the logr docs and try to wrap my head around why this is supposed to be better before commenting further.

@hiddeco pointed out that realistically, we'd use constants we defined ourselves for the levels.

I'm still left feeling that logger.V(logging.LevelDebug).Info(...) is all at once wordier and less expressive than logger.Debug(...).

I'm totally bought into the benefits of logr, but just cannot get over the interface.

Wondering what @jessesuen and @hiddeco might think about a thin wrapper around logr.Logger in our existing logging package. logging.DefaultLogger() and logging.LoggerFromContext(ctx) could be modified to return something that looks like this:

type Logger struct { *logr.Logger } func (l *Logger) Debug(msg string, keysAndValues ...any) { l.Logger.V(LevelDebug).Info(msg, keysAndValues...) } // Similar for trace, warn, error, etc. func (l *Logger) WithValues(keysAndValues ...any) *Logger { newLogger := l.Logger.WithValues(keysAndValues...) return &Logger{Logger: &newLogger} }

To be clear... I'm not proposing an "abstraction over an abstraction." I'm proposing fully taking advantage of the logr abstraction (i.e. we can still swap logging back ends no problem), but merely enhancing their interface without obscuring access in case we sometimes need to "drop-down" to it.

On one hand, I feel averse of this idea because it does not allow you to log errors at debug level, which a real logr.Logger implementation does allow you to do.

I also think (and know based on experience), the problem can largely be worked around by using a modular approach in your application architecture. Allowing you to e.g. inject a logr.Logger instance at a predefined level, so that you have to think less about the level which you are logging at.

On the other hand, is the question how often you really have the desire to log an error at debug level, and isn't this approach really uncommon in our landscape.

it does not allow you to log errors at debug level

Keep in mind, we wouldn't lose access to the underlying logr.Logger.

Allowing you to e.g. inject a logr.Logger instance at a predefined level

To be clear, my concern isn't so much about obtaining a logger that logs at a certain level of verbosity. My concern is the logr interface makes it harder to express the relative importance of an individual message.

And lol at that link being almost exactly what I described.

I don't have a philosophical attachment to the principles of go-logr. A lot of the stuff in the go-logr FAQ is quite principled. I'm not a go-logr purist so we don't have to fully accept their interface as-is. The main use case I was concerned with was that we didn't have a way of setting a logger to sigs.k8s.io/controller-runtime/pkg/log, which wants a logr.Logger.

I'm fine with creating the wrapper that embeds logr.Logger, especially if it maintains our code readability while also addressing the initial use case. The underlying logr.Logger is always available if we wish to use the lower interface.

FWIW logger.Debug(...) is definitely preferrable over logger.V(logging.LevelDebug).Info(...) and so if we had to switch all our logging statements to the 2nd version, that might be reason enough to create our wrapper.

Thanks @jessesuen.

@bakunowski are you game for adding a wrapper like the one @hiddeco linked to in our existing logging package?

internal/api/server.go

krancour · 2024-04-09T01:33:01Z

internal/api/option/log.go

+ WithValues(fields).
+ V(int(level)).
+ Info("finished streaming call")


I'm not sure this accomplishes the same thing as the old call. This change seems to use a logger with a particular verbosity, but doesn't seem to change the level of the message itself.

Sorry, this one slipped me. I think the level is right, as I attempted to explain here, but AFAIK there's no way to specify an error level log with V().

I think the changes in 1edbe52 should put us back on track.

krancour · 2024-04-09T01:35:41Z

internal/controller/promotion/composite.go

@@ -54,7 +54,7 @@ func (c *compositeMechanism) Promote(
 newFreight = *newFreight.DeepCopy()

 logger := logging.LoggerFromContext(ctx)
- logger.Debugf("executing %s", c.name)
+ logger.V(1).Info("executing", "name", c.name)


It seems as if the level of many of the messages has changed.

logger.V(1).Info == logger.Debug()
logger.V(2).Info == logger.Trace()

An attempt at an explanation: #1791 (comment)

cmd/controlplane/controller.go

internal/controller/promotions/promoqueues.go

krancour · 2024-04-09T01:46:46Z

internal/controller/stages/stages.go

@@ -567,7 +566,7 @@ func (r *reconciler) Reconcile(
 if err == nil {
 err = errors.Join(updateErr, clearErr)
 }
- logger.Debug("done reconciling Stage")
+ logger.V(1).Info("done reconciling Stage")


More cases of levels that seem to have changed?

internal/controller/stages/watches.go

krancour · 2024-04-09T01:58:27Z

@bakunowski thank you so much for tackling this.

I left a number of comments -- and many of them are applicable in many places other than where I pointed them out. I didn't want to get carried away pointing out every instance of a general something I had feedback on...

Please don't let the number of comments fool you into thinking this PR is anything less than awesome. I am so happy to see progress on this! This is, unfortunately, just what happens when some cross-cutting concern like logging receives a broad update.

We're on the right track! 🙏

hiddeco · 2024-04-10T08:56:52Z

internal/logging/context.go

-func LoggerFromContext(ctx context.Context) *log.Entry {
+// LoggerFromContext extracts a logr.Logger from the provided context.Context and
+// returns it. If no logr.Logger is found, a global logr.Logger is returned.
+func LoggerFromContext(ctx context.Context) logr.Logger {


Wondering if at this point, it wouldn't simply be better to make use of the tooling that comes with controller-runtime: https://pkg.go.dev/sigs.k8s.io/controller-runtime/pkg/log#pkg-index

@hiddeco I've had the same thought previously and have held off so-far because our logging package also does some logger initialization based on environment variables. If we stop relying on that, we need to come up with another way of doing that. I'm open to it, but think it should be handled in a follow-up.

I had missed the init magic, and while I do think it would be possible to do this by other means. I do agree it shouldn't be part of this PR.

while I do think it would be possible to do this by other means

100%

bakunowski · 2024-04-17T14:45:25Z

@bakunowski thank you so much for tackling this.

I left a number of comments -- and many of them are applicable in many places other than where I pointed them out. I didn't want to get carried away pointing out every instance of a general something I had feedback on...

Please don't let the number of comments fool you into thinking this PR is anything less than awesome. I am so happy to see progress on this! This is, unfortunately, just what happens when some cross-cutting concern like logging receives a broad update.

We're on the right track! 🙏

Thanks for the detailed review! Sounds good, I didn't expect this to go down easy 😄

Sorry about the delay in getting back - last week has been pretty busy. I'll try to address the comments and make changes where it's clear what they should be.

Signed-off-by: Karol Bakunowski <[email protected]>

hiddeco · 2024-04-19T11:02:42Z

internal/logging/context.go

+ opts := &slog.HandlerOptions{
+ Level: programLevel,
+ ReplaceAttr: func(groups []string, a slog.Attr) slog.Attr {
+ // Customize the name of the level key and the output string,
+ // including custom level values. Meaning:
+ // log.V(1).Info() becomes level=DEBUG instead of level=DEBUG+3
+ // log.V(2).Info() becomes level=TRACE instead of level=DEBUG+2
+ if a.Key == slog.LevelKey {
+ // Handle custom level values.
+ level := a.Value.Any().(slog.Level)
+
+ switch {
+ case level < LevelDebug:
+ a.Value = slog.StringValue(TRACE)
+ case level < LevelInfo:
+ a.Value = slog.StringValue(DEBUG)
+ case level < LevelError:
+ a.Value = slog.StringValue(INFO)
+ default:
+ a.Value = slog.StringValue(ERROR)
+ }
+ }
+ return a
+ },
+ }
+
+ globalLogger = logr.FromSlogHandler(slog.NewTextHandler(os.Stderr, opts))
+
 SetKLogLevel(os.GetEnvInt("KLOG_LEVEL", 0))


I wonder how much of https://github.com/go-logr/logr#using-a-logrlogsink-as-backend-for-slog is applicable here...

hiddeco · 2024-04-19T11:34:22Z

internal/logging/context.go

+ // Customize the name of the level key and the output string,
+ // including custom level values. Meaning:
+ // log.V(1).Info() becomes level=DEBUG instead of level=DEBUG+3
+ // log.V(2).Info() becomes level=TRACE instead of level=DEBUG+2


It would probably be wise to align this with the upstream levels of our arguably biggest dependency. https://github.com/kubernetes/community/blob/master/contributors/devel/sig-instrumentation/logging.md#what-method-to-use

krancour · 2024-04-22T14:36:17Z

As we're approaching a v0.6.0 release and there's a sizeable amount of work outstanding here, this is being deferred to v0.7.0.

bakunowski requested a review from a team as a code owner April 7, 2024 14:02

bakunowski force-pushed the logr branch from 1fee5ed to a5b2014 Compare April 7, 2024 14:04

bakunowski commented Apr 7, 2024

View reviewed changes

bakunowski force-pushed the logr branch from a5b2014 to cf4fbbb Compare April 7, 2024 15:41

krancour assigned krancour and bakunowski Apr 7, 2024

krancour added this to the v0.6.0 milestone Apr 8, 2024

krancour added kind/refactor priority/normal area/tech-debt labels Apr 8, 2024