Logging

Overview

Operator SDK uses a -based logr backend when scaffolding new projects. To assist with configuring and using this logger, the SDK includes several helper functions.

In the simple example below, we add the zap flagset to the operator’s command line flags with BindFlags(), and then set the controller-runtime logger with zap.Options{}.

By default, zap.Options{} will return a logger that is ready for production use. It uses a JSON encoder, logs starting at the info level. To customize the default behavior, users can use the zap flagset and specify flags on the command line. The zap flagset includes the following flags that can be used to configure the logger:

  • --zap-devel: Development Mode defaults(encoder=consoleEncoder,logLevel=Debug,stackTraceLevel=Warn) Production Mode defaults(encoder=jsonEncoder,logLevel=Info,stackTraceLevel=Error)
  • --zap-encoder: Zap log encoding (‘json’ or ‘console’)
  • --zap-log-level: Zap Level to configure the verbosity of logging. Can be one of ‘debug’, ‘info’, ‘error’, or any integer value > 0 which corresponds to custom debug levels of increasing verbosity”)
  • --zap-stacktrace-level: Zap Level at and above which stacktraces are captured (one of ‘info’ or ‘error’)

Consult the controller-runtime for more detailed flag information.

Operators set the logger for all operator logging in main.go. To illustrate how this works, try out this simple example:

Output using the defaults

  1. $ go run main.go
  2. INFO[0000] Running the operator locally in namespace default.
  3. {"level":"info","ts":1587741740.407766,"logger":"global","msg":"Printing at INFO level"}
  4. {"level":"info","ts":1587741740.407855,"logger":"scoped","msg":"Printing at INFO level"}

Output overriding the log level to 1 (debug)

  1. $ go run main.go --zap-log-level=debug
  2. INFO[0000] Running the operator locally in namespace default.
  3. {"level":"info","ts":1587741837.602911,"logger":"global","msg":"Printing at INFO level"}
  4. {"level":"debug","ts":1587741837.602964,"logger":"global","msg":"Printing at DEBUG level"}
  5. {"level":"info","ts":1587741837.6029708,"logger":"scoped","msg":"Printing at INFO level"}

Below is an example illustrating the use of zap-logfmt in logging.

In your main.go file, replace the current implementation for logs inside the main function:

With:

  1.     import(
  2.     ...
  3.     zaplogfmt "github.com/sykesm/zap-logfmt"
  4.     uzap "go.uber.org/zap"
  5.     "go.uber.org/zap/zapcore"
  6.     logf "sigs.k8s.io/controller-runtime/pkg/log"
  7.     "sigs.k8s.io/controller-runtime/pkg/log/zap"
  8.     ...
  9. )
  10.     configLog := uzap.NewProductionEncoderConfig()
  11.     configLog.EncodeTime = func(ts time.Time, encoder zapcore.PrimitiveArrayEncoder) {
  13.     }
  14.     logfmtEncoder := zaplogfmt.NewEncoder(configLog)
  16.     // Construct a new logr.logger.
  17.     logger := zap.New(zap.UseDevMode(true), zap.WriteTo(os.Stdout), zap.Encoder(logfmtEncoder))
  18.     logf.SetLogger(logger)

NOTE: For this example, you will need to add the module "github.com/sykesm/zap-logfmt" to your project. Run go get -u github.com/sykesm/zap-logfmt.

Output using custom zap logger

  1. $ go run main.go
  2. ts=2020-04-30T20:35:59.551268Z level=info logger=global msg="Printing at INFO level"
  3. ts=2020-04-30T20:35:59.551314Z level=debug logger=global msg="Printing at DEBUG level"
  4. ts=2020-04-30T20:35:59.551318Z level=info logger=scoped msg="Printing at INFO level"
  5. ts=2020-04-30T20:35:59.55132Z level=debug logger=scoped msg="Printing at DEBUG level"

By using sigs.k8s.io/controller-runtime/pkg/log, your logger is propagated through controller-runtime. Any logs produced by controller-runtime code will be through your logger, and therefore have the same formatting and destination.

Make sure to have your run target to take ARGS as shown below in Makefile.

  1. # Run against the configured Kubernetes cluster in ~/.kube/config
  2. run: generate fmt vet manifests

When deploying your operator to a cluster you can set additional flags using an args array in your operator’s container spec in the file config/default/manager_auth_proxy_patch.yaml For example:

  1. apiVersion: apps/v1
  2. kind: Deployment
  3. metadata:
  4.   name: controller-manager
  5.   namespace: system
  6. spec:
  7.   template:
  9.       containers:
  10.       - name: kube-rbac-proxy
  11.         image: gcr.io/kubebuilder/kube-rbac-proxy:v0.5.0
  12.         args:
  13.         - "--secure-listen-address=0.0.0.0:8443"
  14.         - "--upstream=http://127.0.0.1:8080/"
  15.         - "--logtostderr=true"
  16.         - "--v=10"
  17.         ports:
  18.         - containerPort: 8443
  19.           name: https
  20.       - name: manager
  21.         args:
  22.         - "--metrics-addr=127.0.0.1:8080"
  23.         - "--enable-leader-election"
  24.         - "--zap-encoder=console"
  25.         - "--zap-log-level=debug"

There are two ways to create structured logs with logr. You can create new loggers using log.WithValues(keyValues) that include keyValues, a list of key-value pair interface{}‘s, in each log record. Alternatively you can include keyValues directly in a log statement, as all logr log statements take some message and keyValues. The signature of logr.Error() has an error-type parameter, which can be nil.

An example from memcached_controller.go:

Log records will look like the following (from log.Error() above):