Operator-sdk: Default logger for the SDK

[lilic]

Setting log level and adding verbose flag would be useful as it'd be nice to give some visibility to the user about what is happening.

[AlexNPavel]

This is definitely something that could be very useful for users. At the moment, I don't believe we're using a logging library for the commands that supports different levels. There are a couple of options that we could use like logrus or glog. We then need to go through all the logging and print statements in commands (maybe other parts of the project as well) and set a log type. This would be quite a big undertaking, but probably worth it int the long run. We should probably discuss this more in the team slack or weekly syncs and post updates here when we decide how to tackle this.

[AlexNPavel]

At the moment, there are various parts of the project already using logrus, so that may be the better option

[shawn-hurley]

I would vote that the project moves to logr which is used by controller runtime, and uses either zap or glog as the actual logger and controller runtime uses zap I believe.

Also, currently it seems that the operator-sdk is using env vars for most of these options and I would like to see these exposed as a command line flag. WDYT?

[CSdread]

I vote for logrus, it is very mature, and is the preferred for our company due to its feature set. I also would like to see both env vars and command line flags supported for all options. Could be nice to even specify as a yaml/json configuration file. I am a -1 on glog as I find it is not built with idiomatic practices of good go code

[lilic]

At the moment, there are various parts of the project already using logrus, so that may be the better option

I vote for logrus

I agree with logrus. While logr does look intersting, I would disagree in using glog, as upstream is also trying to move away from me as well. zap sounds good for performence but maybe logrus which we already use could be the better choice for now.

[hasbro17]

@shawn-hurley The main benefit of using logr(with zap) is that the logs will be consistent with the controller-runtime's logs if you turn on those logs with logf.SetLogger(logf.ZapLogger(false)).

I have no experience with zap or logr so I might not be using it correctly but I took a stab at it to compare the experience with logrus.

import logf "sigs.k8s.io/controller-runtime/pkg/runtime/log"
...
         // Development config (stacktraces on warnings, no sampling)
    zapLogr := logf.ZapLogger(true).WithName("main")
    zapLogr.Info("test info")
    zapLogr.Error(errors.New("my custom error"), "my sample error message")
    zapLogr.V(0).Info("test V(0)")
    zapLogr.V(1).Info("test V(1)")
        zapLogr.V(2).Info("test V(2)")

shows:

2018-10-11T15:03:53.846-0700    INFO    main    manager/main.go:34  test info
2018-10-11T15:03:53.846-0700    ERROR   main    manager/main.go:35  my sample error message {"error": "my custom error"}
github.com/example-inc/memcached-operator/vendor/github.com/go-logr/zapr.(*zapLogger).Error
    /Users/haseeb/work/go-space/src/github.com/example-inc/memcached-operator/vendor/github.com/go-logr/zapr/zapr.go:128
main.main
    /Users/haseeb/work/go-space/src/github.com/example-inc/memcached-operator/cmd/manager/main.go:35
runtime.main
    /usr/local/go/src/runtime/proc.go:198
2018-10-11T15:03:53.846-0700    INFO    main    manager/main.go:36  test V(0)
2018-10-11T15:03:53.846-0700    DEBUG   main    manager/main.go:37  test V(1)

zapLogr.V(2).Info("test V(2)") wasn't printed out. Not sure how to enable that.

And if I use logf.ZapLogger(true) or production mode:

import logf "sigs.k8s.io/controller-runtime/pkg/runtime/log"
...
         // Development config (stacktraces on errors, sampling)
    zapLogr := logf.ZapLogger(true).WithName("main")

it shows:

{"level":"info","ts":1539295698.2198892,"logger":"main","caller":"manager/main.go:34","msg":"test info"}
{"level":"error","ts":1539295698.2199519,"logger":"main","caller":"manager/main.go:35","msg":"my sample error message","error":"my custom error","stacktrace":"github.com/example-inc/memcached-operator/vendor/github.com/go-logr/zapr.(*zapLogger).Error\n\t/Users/haseeb/work/go-space/src/github.com/example-inc/memcached-operator/vendor/github.com/go-logr/zapr/zapr.go:128\nmain.main\n\t/Users/haseeb/work/go-space/src/github.com/example-inc/memcached-operator/cmd/manager/main.go:35\nruntime.main\n\t/usr/local/go/src/runtime/proc.go:198"}
{"level":"info","ts":1539295698.2199934,"logger":"main","caller":"manager/main.go:36","msg":"test V(0)"}

And logrus for comparison:

    logrus.SetFormatter(&logrus.TextFormatter{
        FullTimestamp: true,
    })
    logrus.SetLevel(logrus.DebugLevel)
    logger := logrus.WithFields(logrus.Fields{"component": "main"})
    logger.Info("test info")
    logger.Print("test print")
    logger.Errorf("my custom error: %v", errors.New("my sample error message"))
    logger.Debug("test debug")
    logger.Warn("test warning")
    logger.Fatal("test fatal")

gives us:

INFO[2018-10-11T15:36:09-07:00] test info                                     component=main
INFO[2018-10-11T15:36:09-07:00] test print                                    component=main
ERRO[2018-10-11T15:36:09-07:00] my custom error: my sample error message      component=main
DEBU[2018-10-11T15:36:09-07:00] test debug                                    component=main
WARN[2018-10-11T15:36:09-07:00] test warning                                  component=main
FATA[2018-10-11T15:36:09-07:00] test fatal                                    component=main

From a usability perspective do you think logr's interface is more intuitive or useful than logrus?
Enough so that we recommend that as our default prescribed logger in the templates?

Right now in the refactor branch we've stepped back from using logrus since I didn't want to presume what kind of logger should be used and would rather leave it up to the user. At least until we can decide.
https://github.com/operator-framework/operator-sdk/blob/refactor/controller-runtime/pkg/scaffold/cmd.go#L53-L57

[shawn-hurley]

I think what we may want to consider, is implementing a logrus backend for logr.

logr appears to me to be nothing more than a standard interface for logging. If we choose to use the logr interface then

1. users could implement their own backends for whichever logger they want all we need to do is expose something like this.

1. This could could be filtered down to controller-runtime so our logs look the same as their logs.

Here is the logr interface implementation: https://github.com/go-logr/logr/blob/master/logr.go#L120

And if you want to know how to get .V2() logging look here: https://github.com/go-logr/zapr
Specifically this line:

Levels in logr correspond to custom debug levels in Zap. Any given level in logr is represents by its inverse in Zap (zapLevel = -1*logrLevel).

For example V(2) is equivalent to log level -2 in Zap, while V(1) is equivalent to Zap's DebugLevel.

This will give users more choice, will allow folks to get logrus as a defualt (which I think looks nicer IMO) and our logs can then look exactly like controller-runtimes logs because we just set their logr as our implementation.

Does this all make sense?

[estroz]

I am partial to using logrus for various reasons, including but not limited to:

• Project maturity.
• logrus takes care of our log.Fatal*(...) usage, whereas logr doesn't like that level of control.
• We can format our log entries however we want by implementing a logrus.Formatter, allowing the SDK to copy zap format @hasbro17.

@shawn-hurley writing a logrus backend for logr would be the most reasonable solution to me if not for the latter two reasons above.

[shawn-hurley]

Responding in line with my thoughts to your arguments, I think we probably want to time-box a decision on this and switch to one or the other while we are in high levels of change right now IMO. /cc @hasbro17

Project maturity.

Zap logging is at version 1.2.0 logrus is 1.9.3 I don't know I see a big enough difference to validate a huge differentiator.

logrus takes care of our log.Fatal*(...) usage, whereas logr doesn't like that level of control.

Yeah, we will have to decouple the panic from the log statement. It does add more code but I think is probably more obvious of what we are doing than relying on readers of the code from knowing that Fatal will exit.

We can format our log entries however we want by implementing a logrus.Formatter, allowing the SDK to copy zap format @hasbro17.

This is true until the end user wants to create their logging format. Now they would have to know to set both the logrus.Formatter as well as changing the logr implementation for the controller-runtime bits.

The last point I will make is, we are no longer the primary source of logs for a running operator, instead controller runtime is, I think it might be easier to fall in line with their choices than try and force compatibility.

[estroz]

@shawn-hurley logr has several lines like these that lead me to believe their interface is more immature than logrus'. I could be wrong though, and maturity isn't a blocker for us now regardless.

I agree with your point about us not being the primary log source anymore and would rather the user not have to deal with divergences in log engines.

[hasbro17]

Summarizing our offline discussions here:

The consensus is to use logr as the default logging interface for the SDK(within internal pkgs and the generated templates).
The main reason for this is so that the SDK's logs are of the same format as logs from the controller-runtime pkgs(controller, manager etc).

To start off we can use the zap implementation of logr within the SDK.
https://github.com/kubernetes-sigs/controller-runtime/blob/master/pkg/runtime/log/log.go#L36

And as a followup we can provide an interface to allow users to set the logr implementation for both the SDK and the controller-runtime.
https://github.com/kubernetes-sigs/controller-runtime/blob/master/pkg/runtime/log/log.go#L87-L98

We can also provide a logrus backend for logr to allow changing the implementation from zap to logrus.
The exact implementation needs to be worked out a bit more since logr's interface doesn't map directly onto logrus but a rough outline could be:

• logr.Info() ==> logrus.Info()
• logr.Error() ==> logrus.Error()
• logr.V(0) ==> logr.Warn()
• logr.V(1) ==> logrus.Debug()
• logr.V(2) ==> logrus.Debug()

And with all of the above users should still be free to disregard the SDK's logger and use their own logging solution for their operator.