Logging

Overview

Operator SDK-generated operators use the logr interface to log. This log interface has several backends such as zap, which the SDK uses in generated code by default. logr.Logger exposes structured logging methods that help create machine-readable logs and adding a wealth of information to log records.

Default zap logger

Operator SDK uses a zap-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 ‘warn’ or ‘error’)

Consult the controller-runtime godocs for more detailed flag information.

A simple example

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

  1. package main
  3. import (
  4.     "sigs.k8s.io/controller-runtime/pkg/log/zap"  
  5.     logf "sigs.k8s.io/controller-runtime/pkg/log"
  6. )
  8. var globalLog = logf.Log.WithName("global")
  9. func main() {
  10.     // Add the zap logger flag set to the CLI. The flag set must
  11.     // be added before calling flag.Parse().
  12.     opts := zap.Options{}
  13.     opts.BindFlags(flag.CommandLine)
  14.     flag.Parse()
  16.     logger := zap.New(zap.UseFlagOptions(&opts))
  17.     logf.SetLogger(logger)
  19.     scopedLog := logf.Log.WithName("scoped")
  21.     globalLog.Info("Printing at INFO level")
  22.     globalLog.V(1).Info("Printing at DEBUG level")
  23.     scopedLog.Info("Printing at INFO level")
  24.     scopedLog.V(1).Info("Printing at DEBUG level")
  25. }

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"}
  6. {"level":"debug","ts":1587741837.602973,"logger":"scoped","msg":"Printing at DEBUG level"}

Custom zap logger

In order to use a custom zap logger, zap from controller-runtime can be utilized to wrap it in a logr implementation.

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

Example

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

  1. ...
  2. // Add the zap logger flag set to the CLI. The flag set must
  3. // be added before calling flag.Parse().
  4.     opts := zap.Options{}
  5.     opts.BindFlags(flag.CommandLine)
  6.     flag.Parse()
  8.     logger := zap.New(zap.UseFlagOptions(&opts))
  9.     logf.SetLogger(logger)
  10. ...

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) {
  12.         encoder.AppendString(ts.UTC().Format(time.RFC3339Nano))
  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.

Setting flags when running locally

When running locally with make run ENABLE_WEBHOOKS=false, you can use the ARGS var to pass additional flags to your operator, including the zap flags. For example:

  1. $ make run ARGS="--zap-encoder=console" ENABLE_WEBHOOKS=false

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
  3.     go run ./main.go $(ARGS)

Setting flags when deploying to a cluster

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:
  8.     spec:
  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"

Creating a structured log statement

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:

  1. package memcached
  3. import (
  4.     "github.com/go-logr/logr"
  5. )
  8. // MemcachedReconciler reconciles a Memcached object
  9. type MemcachedReconciler struct {
  10.     client.Client
  11.     Log    logr.Logger
  12.     Scheme *runtime.Scheme
  13. }
  15. func (r *MemcachedReconciler) Reconcile(req ctrl.Request) (ctrl.Result, error) {
  16.     ctx := context.Background()
  17.     log := r.Log.WithValues("memcached", req.NamespacedName)
  19.     // Fetch the Memcached instance
  20.     memcached := &cachev1alpha1.Memcached{}
  21.     err := r.Get(ctx, req.NamespacedName, memcached)
  22.     if err != nil {
  23.         if errors.IsNotFound(err) {
  24.             // Request object not found, could have been deleted after reconcile request.
  25.             // Owned objects are automatically garbage collected. For additional cleanup logic use finalizers.
  26.             // Return and don't requeue
  27.             log.Info("Memcached resource not found. Ignoring since object must be deleted")
  28.             return ctrl.Result{}, nil
  29.         }
  30.         // Error reading the object - requeue the request.
  31.         log.Error(err, "Failed to get Memcached")
  32.         return ctrl.Result{}, err
  33.     }
  35.     // Check if the deployment already exists, if not create a new one
  36.     found := &appsv1.Deployment{}
  37.     err = r.Get(ctx, types.NamespacedName{Name: memcached.Name, Namespace: memcached.Namespace}, found)
  38.     if err != nil && errors.IsNotFound(err) {
  39.         // Define a new deployment
  40.         dep := r.deploymentForMemcached(memcached)
  41.         log.Info("Creating a new Deployment", "Deployment.Namespace", dep.Namespace, "Deployment.Name", dep.Name)
  42.         err = r.Create(ctx, dep)
  43.         if err != nil {
  44.             log.Error(err, "Failed to create new Deployment", "Deployment.Namespace", dep.Namespace, "Deployment.Name", dep.Name)
  45.             return ctrl.Result{}, err
  46.         }
  47.         // Deployment created successfully - return and requeue
  48.         return ctrl.Result{Requeue: true}, nil
  49.     } else if err != nil {
  50.         log.Error(err, "Failed to get Deployment")
  51.         return ctrl.Result{}, err
  52.     }
  54.     ...
  55. }

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

  1. 2020-04-27T09:14:15.939-0400    ERROR    controllers.Memcached    Failed to create new Deployment    {"memcached": "default/memcached-sample", "Deployment.Namespace": "default", "Deployment.Name": "memcached-sample"}

Non-default logging

If you do not want to use logr as your logging tool, you can remove logr-specific statements without issue from your operator’s code, including the logr setup code in main.go, and add your own. Note that removing logr setup code will prevent controller-runtime from logging.

Last modified July 17, 2020: [docs] Reorganize hugo doc site (#3382) (1248c1ca)