Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Proposal: Use klog as kubebuilder default logger #3036

Closed
astraw99 opened this issue Oct 23, 2022 · 19 comments
Closed

Proposal: Use klog as kubebuilder default logger #3036

astraw99 opened this issue Oct 23, 2022 · 19 comments
Labels
kind/feature Categorizes issue or PR as related to a new feature.

Comments

@astraw99
Copy link
Contributor

astraw99 commented Oct 23, 2022

What do you want to happen?

Using the latest kubebuilder cli, quick start a new project based on the official document.
After make deploy IMG=xxx/xxx:tag, the controller-pod log time is just long numbers (1.6656692709539523e+09):

1.6656692709539523e+09  INFO    controller-runtime.metrics      Metrics server is starting to listen    {"addr": "127.0.0.1:8080"}
1.665669270954326e+09   INFO    setup   starting manager
1.6656692709546785e+09  INFO    Starting server {"path": "/metrics", "kind": "metrics", "addr": "127.0.0.1:8080"}
1.6656692709546802e+09  INFO    Starting server {"kind": "health probe", "addr": "[::]:8081"}
I1013 13:54:30.954681       1 leaderelection.go:248] attempting to acquire leader lease demo/demo-controller-manager...
I1013 13:54:30.961182       1 leaderelection.go:258] successfully acquired lease demo/demo-controller-manager
1.6656692709613848e+09  INFO    Starting EventSource    {"controller": "demo", "controllerGroup": "demo.domain.com", "controllerKind": "Demo", "source": "kind source: *v1beta1.Demo"}
1.66566927096143e+09    INFO    Starting Controller     {"controller": "demo", "controllerGroup": "demo.domain.com", "controllerKind": "Demo"}
1.6656692709612472e+09  DEBUG   events  demo-controller-manager-5fdd9c945d-6dgmr_0bba29ee-109a-4ced-add9-d773c4ff839f became leader     {"type": "Normal", "object": {"kind":"Lease","namespace":"demo","name":"demo-controller-manager","uid":"dc9449e9-d589-4c2e-a0ab-5835f4ab96a4","apiVersion":"coordination.k8s.io/v1","resourceVersion":"130007662"}, "reason": "LeaderElection"}
1.665669271061787e+09   INFO    Starting workers        {"controller": "demo", "controllerGroup": "demo.domain.com", "controllerKind": "Demo", "worker count": 1}

Should make it human readable like:

I1013 13:54:30.954681       1 leaderelection.go:248] attempting to acquire leader lease demo/demo-controller-manager...
I1013 13:54:30.961182       1 leaderelection.go:258] successfully acquired lease demo/demo-controller-manager

Related issue: kubernetes-sigs/controller-runtime#2024

With the latest PR merged: kubernetes-sigs/controller-runtime#2029, tried using it got the log:

go get sigs.k8s.io/controller-runtime@090611b34874e78792f30a36d9fa20f2c6de9abb
make run

2022-10-22T18:06:01+08:00       INFO    controller-runtime.metrics      Metrics server is starting to listen    {"addr": ":8080"}
2022-10-22T18:06:01+08:00       INFO    setup   starting manager
2022-10-22T18:06:01+08:00       INFO    controller-runtime.webhook.webhooks     Starting webhook server
2022-10-22T18:06:01+08:00       INFO    Starting server {"path": "/metrics", "kind": "metrics", "addr": "[::]:8080"}
2022-10-22T18:06:01+08:00       INFO    Starting server {"kind": "health probe", "addr": "[::]:8081"}
2022-10-22T18:06:01+08:00       INFO    Stopping and waiting for non leader election runnables
2022-10-22T18:06:01+08:00       INFO    Stopping and waiting for leader election runnables
I1022 18:06:01.310466   82983 leaderelection.go:248] attempting to acquire leader lease demo/demo-controller-manager...
2022-10-22T18:06:01+08:00       INFO    Starting EventSource    {"controller": "demo", "controllerGroup": "demo.domain.com", "controllerKind": "Demo", "source": "kind source: *v1beta1.Demo"}
2022-10-22T18:06:01+08:00       INFO    Starting Controller     {"controller": "demo", "controllerGroup": "demo.domain.com", "controllerKind": "Demo"}
2022-10-22T18:06:01+08:00       INFO    Starting workers        {"controller": "demo", "controllerGroup": "demo.domain.com", "controllerKind": "Demo", "worker count": 1}

But the result log format (no file and line info) is not consistent with the klog format, as in the upper leaderelection line.
So propose to use klog to make it consistent with the K8s core components, like:

I1016 23:41:42.700531   61722 listener.go:44] "controller-runtime/metrics: Metrics server is starting to listen" addr=":8080"
I1016 23:41:42.701073   61722 main.go:115] "setup: starting manager"
I1016 23:41:42.701251   61722 internal.go:362] "Starting server" kind="health probe" addr="[::]:8081"
I1016 23:41:42.701255   61722 internal.go:362] "Starting server" path="/metrics" kind="metrics" addr="[::]:8080"

Pros

  • Make the log format human readable (with file and line info)
  • Keep consistent with the K8s core components (kube-apiserver/controller-manager)
  • Also support customized option flags by klog.InitFlags(klogFlags)
  • Remove dependency on zap logger

Cons

  • Add a new klog dependency

Extra Labels

No response

@astraw99 astraw99 added the kind/feature Categorizes issue or PR as related to a new feature. label Oct 23, 2022
@astraw99
Copy link
Contributor Author

@camilamacedo86
Copy link
Member

camilamacedo86 commented Oct 24, 2022

Hi @astraw99,

By looking at your example using klog: (proposed PR changes #3033 )

I1016 23:41:42.700531   61722 listener.go:44] "controller-runtime/metrics: Metrics server is starting to listen" addr=":8080"
I1016 23:41:42.701073   61722 main.go:115] "setup: starting manager"
I1016 23:41:42.701251   61722 internal.go:362] "Starting server" kind="health probe" addr="[::]:8081"
I1016 23:41:42.701255   61722 internal.go:362] "Starting server" path="/metrics" kind="metrics" addr="[::]:8080"
  • It is not logging the controllers/kind that will be reconciled
  • it does not provide diff levels to allow admins to increase them to debug level for example
  • it does not allow config by flags.

Am I right?
So, could you please check that and see if would be possible to ensure that the same behaviours with as well?

Note that the logs done by controller-runtime by default (as it is today) adopt the same k8s format. Regards the time format not parse for humans it will be solved in the next controller-runtime release and when we bump it on Kubebuilder, see: kubernetes-sigs/controller-runtime#2029

@astraw99
Copy link
Contributor Author

astraw99 commented Oct 24, 2022

@camilamacedo86

  1. The above controllers/kind part is just omitted for short, this is the whole log:
I1024 23:04:47.680350   46382 listener.go:44] "controller-runtime/metrics: Metrics server is starting to listen" addr=":8080"
I1024 23:04:47.680974   46382 main.go:141] "setup: starting manager"
I1024 23:04:47.681130   46382 internal.go:362] "Starting server" kind="health probe" addr="[::]:8081"
I1024 23:04:47.681179   46382 internal.go:362] "Starting server" path="/metrics" kind="metrics" addr="[::]:8080"
I1024 23:04:47.681240   46382 controller.go:185] "Starting EventSource" controller="demo" controllerGroup="demo.domain.com" controllerKind="Demo" source="kind source: *v1beta1.Demo"
I1024 23:04:47.681242   46382 controller.go:185] "Starting EventSource" controller="demo1" controllerGroup="demo.domain.com" controllerKind="Demo1" source="kind source: *v1beta1.Demo1"
I1024 23:04:47.681261   46382 controller.go:193] "Starting Controller" controller="demo" controllerGroup="demo.domain.com" controllerKind="Demo"
I1024 23:04:47.681269   46382 controller.go:193] "Starting Controller" controller="demo1" controllerGroup="demo.domain.com" controllerKind="Demo1"
I1024 23:04:47.681272   46382 controller.go:185] "Starting EventSource" controller="demo2" controllerGroup="demo.domain.com" controllerKind="Demo2" source="kind source: *v1beta1.Demo2"
I1024 23:04:47.681301   46382 controller.go:193] "Starting Controller" controller="demo2" controllerGroup="demo.domain.com" controllerKind="Demo2"
I1024 23:04:47.783574   46382 controller.go:227] "Starting workers" controller="demo2" controllerGroup="demo.domain.com" controllerKind="Demo2" worker count=1
I1024 23:04:47.784764   46382 controller.go:227] "Starting workers" controller="demo" controllerGroup="demo.domain.com" controllerKind="Demo" worker count=1
I1024 23:04:47.784784   46382 controller.go:227] "Starting workers" controller="demo1" controllerGroup="demo.domain.com" controllerKind="Demo1" worker count=1
  1. Klog support flag and levels, see examples in:
    https://github.com/kubernetes/klog/blob/main/examples/klogr/main.go
    https://github.com/kubernetes/klog/blob/main/examples/log_file/usage_log_file.go
    https://github.com/kubernetes/klog/tree/main/examples

  2. As said in the proposal above, with the latest controller-runtime by default (as it is today):
    ⚠ Zap log: Default to RFC3339 time encoding controller-runtime#2029
    Tried using it got the log:

go get sigs.k8s.io/controller-runtime@090611b34874e78792f30a36d9fa20f2c6de9abb
make run

2022-10-22T18:06:01+08:00       INFO    controller-runtime.metrics      Metrics server is starting to listen    {"addr": ":8080"}
2022-10-22T18:06:01+08:00       INFO    setup   starting manager
2022-10-22T18:06:01+08:00       INFO    controller-runtime.webhook.webhooks     Starting webhook server
2022-10-22T18:06:01+08:00       INFO    Starting server {"path": "/metrics", "kind": "metrics", "addr": "[::]:8080"}
2022-10-22T18:06:01+08:00       INFO    Starting server {"kind": "health probe", "addr": "[::]:8081"}
2022-10-22T18:06:01+08:00       INFO    Stopping and waiting for non leader election runnables
2022-10-22T18:06:01+08:00       INFO    Stopping and waiting for leader election runnables
I1022 18:06:01.310466   82983 leaderelection.go:248] attempting to acquire leader lease demo/demo-controller-manager...
2022-10-22T18:06:01+08:00       INFO    Starting EventSource    {"controller": "demo", "controllerGroup": "demo.domain.com", "controllerKind": "Demo", "source": "kind source: *v1beta1.Demo"}
2022-10-22T18:06:01+08:00       INFO    Starting Controller     {"controller": "demo", "controllerGroup": "demo.domain.com", "controllerKind": "Demo"}
2022-10-22T18:06:01+08:00       INFO    Starting workers        {"controller": "demo", "controllerGroup": "demo.domain.com", "controllerKind": "Demo", "worker count": 1}

We can see the log format (full-time, no file and line info) is not consistent with the klog format, as in the upper leaderelection line, the desired format should like this:

I1016 23:41:42.700531   61722 listener.go:44] "controller-runtime/metrics: Metrics server is starting to listen" addr=":8080"
I1016 23:41:42.701073   61722 main.go:115] "setup: starting manager"
I1016 23:41:42.701251   61722 internal.go:362] "Starting server" kind="health probe" addr="[::]:8081"
I1016 23:41:42.701255   61722 internal.go:362] "Starting server" path="/metrics" kind="metrics" addr="[::]:8080"
...

@camilamacedo86
Copy link
Member

Hi @astraw99,

Thank you for the clarifications. I am OK with the change proposed https://github.com/kubernetes-sigs/kubebuilder/pull/3033/files. You are not the first one looking for klog but I think would be nice to get others' opinions as well. @jmrodri @varshaprasad96 @everettraven wdyt?

Also, I am not sure why we use

opts := zap.Options{
		Development: true,

In the default scaffold, however, it seems that would be nice to check it out and see if we should not need to ensure the same behaviour with klog.

@grzesuav
Copy link

@astraw99 for human readability you can adjust zap configuration it is very readable logger.

@aerfio
Copy link

aerfio commented Oct 27, 2022

In my personal opinion klog is way less readable than zap 🙈. And zap is way more configurable.

Usually I use zap with json format for logging and redirect klog to zap logger using klog.SetOutput + zapio.Writer/os.Discard, while exposing the klog level indirectly as env var (we dont use flags in my org). It's not ideal 😞.I understand that being consistent with other k8s components would be beneficial though.

Also, anecdotally, in my org we spend way too much time discussing what should be logged at what level, and exposing only debug/info/etc levels keeps it simple. Some people go even further with that idea, see https://github.com/crossplane/crossplane-runtime/blob/fa5545f26b0458d4680502cfc0415048318baa85/pkg/logging/logging.go (I'm not affiliated with them)

@grzesuav
Copy link

grzesuav commented Oct 27, 2022

Currently in go ecosystem logr as interface is frequently used, zap also implements this - https://github.com/go-logr/zapr

Full list - https://github.com/go-logr/logr#implementations-non-exhaustive

Among the choices, zap is rather fast one - https://github.com/uber-go/zap#performance

IMO in scaffolding all places generic logr should be used as interface, with zap configured in init. It allows to easy change the logging backed if anyone need that.

EDIT: I think for scaffolding, using logr interface everywhere, choice of the logger should be even relatively easy made configurable

@everettraven
Copy link
Contributor

wdyt?

@camilamacedo86 reading through some of the comments here I really like the idea proposed by @grzesuav where we potentially change all logging instances in the default scaffold to use a logging interface (as @grzesuav mentioned logr seems to be pretty widely used). What do you think of this @camilamacedo86 ?

@astraw99 I think this approach would satisfy your needs by making the logging much more configurable as long as the logger that will be used satisfies the logr.Logger interface. I think going this route would also only require changes in Kubebuilder as controller-runtime seems to already use the logr.Logger interface and just defaults to using zap.

@camilamacedo86
Copy link
Member

Hi @grzesuav and @everettraven,

@camilamacedo86 reading through some of the comments here I really like the idea proposed by @grzesuav where we potentially change all logging instances in the default scaffold to use a logging interface (as @grzesuav mentioned logr seems to be pretty widely used). What do you think of this @camilamacedo86 ?

WDYT about creating a PR with the suggestions so that we can have a better idea and discuss the proposed solution?

@varshaprasad96
Copy link
Member

/triage-accepted
@grzesuav would you like to create a PR to make logging configurable. This would be a good addition to KB.

@astraw99
Copy link
Contributor Author

astraw99 commented Nov 4, 2022

@grzesuav @camilamacedo86 @varshaprasad96
From the current code:

opts := zap.Options{
Development: true,
}
opts.BindFlags(flag.CommandLine)
flag.Parse()
ctrl.SetLogger(zap.New(zap.UseFlagOptions(&opts)))

We can see the ctrl.SetLogger(...) already use go-logr/zapr as an basic interface, to let the user choose
which logger impl to use.

In this proposal, we just want to use the klog as the default logger impl, the pros and cons are listed above.
PTAL thanks.

@grzesuav
Copy link

@astraw99

looking at what you wrote

Make the log format human readable (with file and line info)

the log format should be machine readable, to be able to be parsed by logstash/kibana/etc

In case you need to change it to human readable in dev env, just run you code with flag

--zap-devel

Keep consistent with the K8s core components (kube-apiserver/controller-manager)

Not sure why it is a pros, k8s komponent are in major refactoring to use structured logging, which isn't easy considering the codebase. Among logr compatibile loggers zap is more perfomant than klog

Also support customized option flags by klog.InitFlags(klogFlags)

The same for zap - https://pkg.go.dev/sigs.k8s.io/controller-runtime/pkg/log/zap#Options.BindFlags

@grzesuav
Copy link

@varshaprasad96 @camilamacedo86 sure, will try to do it over the weekend

@grzesuav
Copy link

@camilamacedo86 @varshaprasad96 after looking onto code it seems there is no much to extract as as @astraw99 noticed the only place which require change is logger initialization and import.

However looking onto code it seems it can be parameterized (i.e. by default generate zap thing, but when some parameter is passed use klog instead)

I can add it, the changes in the template will be (I put NEW MARKER FOR LOGGER... in places requiring change)

var mainTemplate = `{{ .Boilerplate }}

package main

import (
	"flag"
	"os"

	// Import all Kubernetes client auth plugins (e.g. Azure, GCP, OIDC, etc.)
	// to ensure that exec-entrypoint and run can make use of them.
	_ "k8s.io/client-go/plugin/pkg/client/auth"

	"k8s.io/apimachinery/pkg/runtime"
	utilruntime "k8s.io/apimachinery/pkg/util/runtime"
	clientgoscheme "k8s.io/client-go/kubernetes/scheme"
	ctrl "sigs.k8s.io/controller-runtime"
	"sigs.k8s.io/controller-runtime/pkg/log/zap"
        %s - NEW MARKER FOR LOGGER IMPORT
	"sigs.k8s.io/controller-runtime/pkg/healthz"
	%s
)

var (
	scheme = runtime.NewScheme()
	setupLog = ctrl.Log.WithName("setup")
)

func init() {
	utilruntime.Must(clientgoscheme.AddToScheme(scheme))

	%s
}

func main() {
{{- if not .ComponentConfig }}
	var metricsAddr string
	var enableLeaderElection bool
	var probeAddr string
	flag.StringVar(&metricsAddr, "metrics-bind-address", ":8080", "The address the metric endpoint binds to.")
	flag.StringVar(&probeAddr, "health-probe-bind-address", ":8081", "The address the probe endpoint binds to.")
	flag.BoolVar(&enableLeaderElection, "leader-elect", false,
		"Enable leader election for controller manager. " +
		"Enabling this will ensure there is only one active controller manager.")
{{- else }}
  var configFile string
	flag.StringVar(&configFile, "config", "", 
		"The controller will load its initial configuration from this file. " +
		"Omit this flag to use the default configuration values. " +
		"Command-line flags override configuration from this file.")
{{- end }}
	 %s - NEW MARKER FOR LOGGER INIT
	flag.Parse()

	ctrl.SetLogger(%s - NEW MARKER FOR LOGGER SETTING)

want to ask before going forward though

@grzesuav
Copy link

alternative would be to use {{ .LoggerImport }} {{ .LOGGER_INIT }} variables, should be more readable than code generation markers as the code placed there will be rather static

@everettraven
Copy link
Contributor

@grzesuav Thanks for your analysis! Thinking about this a bit more and seeing what @astraw99 commented I personally feel like this should be a no-op.

With the default logging scaffold in the main.go file being:

	opts := zap.Options{
		Development: true,
	}
	opts.BindFlags(flag.CommandLine)
	flag.Parse()

	ctrl.SetLogger(zap.New(zap.UseFlagOptions(&opts)))

It seems like it would pretty trivial to manually convert this to:

	opts.BindFlags(flag.CommandLine)
	flag.Parse()


	ctrl.SetLogger(klog.New())

Since the default scaffolding has been zap for so long I feel like changing it to klog as the default would be considered a "breaking" change due to how many users Kubebuilder has and what their expectations of the default logger being used is.

My suggestion would be that if it isn't made clear in the Kubebuilder documentation how to change the logger that we add a new section to the FAQ about how to do this.

@camilamacedo86 @varshaprasad96 WDYT?

@camilamacedo86
Copy link
Member

camilamacedo86 commented Nov 11, 2022

I agree with @everettraven +1000.Also:

So, (ihmo) I think we could close this one as not accept.

PS.: However, if you folks see that community/users would prefer we scaffold klog by default instead of zap then, ihmo this change should be done only for go-v4/alpha.

c/c @varshaprasad96 @jmrodri

@grzesuav
Copy link

sure thing. IMO changing to klog is easy enough, also as I stated zap is configurable enough with sensible defaults to production use, it can be configured to produce user-readable logs for development also.

Regarding maturity, as I mentioned earlier zap is faster , so changing to klog feels to me like going into wrong direction.

@astraw99
Copy link
Contributor Author

OK, after discussion, we prefer to use zap as default logger.
Will close this proposal.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
kind/feature Categorizes issue or PR as related to a new feature.
Projects
None yet
Development

Successfully merging a pull request may close this issue.

6 participants