Closed astraw99 closed 1 year ago
@camilamacedo86 @alvaroaleman @joelanford c/c @jmrodri @varshaprasad96
Hi @astraw99,
By looking at your example using klog: (proposed PR changes https://github.com/kubernetes-sigs/kubebuilder/pull/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"
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: https://github.com/kubernetes-sigs/controller-runtime/pull/2029
@camilamacedo86
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
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
As said in the proposal above, with the latest controller-runtime by default (as it is today): https://github.com/kubernetes-sigs/controller-runtime/pull/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" ...
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.
@astraw99 for human readability you can adjust zap
configuration it is very readable logger.
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)
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
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
.
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?
/triage-accepted @grzesuav would you like to create a PR to make logging configurable. This would be a good addition to KB.
@grzesuav @camilamacedo86 @varshaprasad96 From the current code: https://github.com/kubernetes-sigs/kubebuilder/blob/15bd05e86b0ce71b0ca03b7d180c9a591d90403d/pkg/plugins/golang/v3/scaffolds/internal/templates/main.go#L232-L238
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.
@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
@varshaprasad96 @camilamacedo86 sure, will try to do it over the weekend
@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
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
@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?
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
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.
OK, after discussion, we prefer to use zap
as default logger.
Will close this proposal.
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):Should make it human readable like:
Related issue: https://github.com/kubernetes-sigs/controller-runtime/issues/2024
With the latest PR merged: https://github.com/kubernetes-sigs/controller-runtime/pull/2029, tried using it got the log:
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 useklog
to make it consistent with the K8s core components, like:Pros
klog.InitFlags(klogFlags)
Cons
Extra Labels
No response