Operator SDK Logging

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 zap.FlagSet(), and then set the controller-runtime logger with zap.Logger().

By default, zap.Logger() will return a logger that is ready for production use. It uses a JSON encoder, logs starting at the info level, and has sampling enabled. 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 - Enables the zap development config (changes defaults to console encoder, debug log level, and disables sampling) (default: false)
  • --zap-encoder string - Sets the zap log encoding (json or console)
  • --zap-level string or integer - Sets the zap log level (debug, info, error, or an integer value greater than 0). If 4 or greater the verbosity of client-go will be set to this level.
  • --zap-sample - Enables zap’s sampling mode. Sampling will be disabled for integer log levels greater than 1.
  • --zap-stacktrace-level - Set the minimum log level that triggers stacktrace generation (default: error)
  • --zap-time-encoding string - Sets the zap time format (epoch, millis, nano, or iso8601)

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
  2. import (
  3. "github.com/operator-framework/operator-sdk/pkg/log/zap"
  4. "github.com/spf13/pflag"
  5. logf "sigs.k8s.io/controller-runtime/pkg/log"
  6. )
  7. var globalLog = logf.Log.WithName("global")
  8. func main() {
  9. pflag.CommandLine.AddFlagSet(zap.FlagSet())
  10. pflag.Parse()
  11. logf.SetLogger(zap.Logger())
  12. scopedLog := logf.Log.WithName("scoped")
  13. globalLog.Info("Printing at INFO level")
  14. globalLog.V(1).Info("Printing at DEBUG level")
  15. scopedLog.Info("Printing at INFO level")
  16. scopedLog.V(1).Info("Printing at DEBUG level")
  17. }

Output using the defaults

  1. $ go run main.go
  2. {"level":"info","ts":1559866292.307987,"logger":"global","msg":"Printing at INFO level"}
  3. {"level":"info","ts":1559866292.308039,"logger":"scoped","msg":"Printing at INFO level"}

Output overriding the log level to 1 (debug)

  1. $ go run main.go --zap-level=1
  2. {"level":"info","ts":1559866310.065048,"logger":"global","msg":"Printing at INFO level"}
  3. {"level":"debug","ts":1559866310.0650969,"logger":"global","msg":"Printing at DEBUG level"}
  4. {"level":"info","ts":1559866310.065119,"logger":"scoped","msg":"Printing at INFO level"}
  5. {"level":"debug","ts":1559866310.065123,"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 pflag.Parse().
  4. pflag.CommandLine.AddFlagSet(zap.FlagSet())
  5. // Add flags registered by imported packages (e.g. glog and
  6. // controller-runtime)
  7. pflag.CommandLine.AddGoFlagSet(flag.CommandLine)
  8. pflag.Parse()
  9. // Use a zap logr.Logger implementation. If none of the zap
  10. // flags are configured (or if the zap flag set is not being
  11. // used), this defaults to a production zap logger.
  12. // The logger instantiated here can be changed to any logger
  13. // implementing the logr.Logger interface. This logger will
  14. // be propagated through the whole operator, generating
  15. // uniform and structured logs.
  16. logf.SetLogger(zap.Logger())
  17. ...

With:

  1. configLog := zap.NewProductionEncoderConfig()
  2. configLog.EncodeTime = func(ts time.Time, encoder zapcore.PrimitiveArrayEncoder) {
  3. encoder.AppendString(ts.UTC().Format(time.RFC3339))
  4. }
  5. logfmtEncoder := zaplogfmt.NewEncoder(configLog)
  6. // Construct a new logr.logger.
  7. log = zapcr.New(zapcr.UseDevMode(true), zapcr.WriteTo(os.Stdout), zapcr.Encoder(logfmtEncoder))
  8. // Set the controller logger to log, which will
  9. // be propagated through the whole operator, generating
  10. // uniform and structured logs.
  11. logf.SetLogger(log)

Ensure that the following additional imports are being used:

  1. import(
  2. ...
  3. zaplogfmt "github.com/sykesm/zap-logfmt"
  4. zapcr "sigs.k8s.io/controller-runtime/pkg/log/zap"
  5. logf "sigs.k8s.io/controller-runtime/pkg/log"
  6. "go.uber.org/zap"
  7. "go.uber.org/zap/zapcore"
  8. ...
  9. )

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.

To test, the following print statement can be added in the main function:

log.Info("Printing at INFO LEVEL")

Output using custom zap logger

  1. $ operator-sdk run local
  2. ts=2020-02-27T23:10:33Z level=info msg="Printing at INFO level"
  3. ts=2020-02-27T23:10:33Z level=info msg="Operator Version: 0.0.1"
  4. ts=2020-02-27T23:10:33Z level=info msg="Go Version: go1.13.8"
  5. ts=2020-02-27T23:10:33Z level=info msg="Go OS/Arch: darwin/amd64"
  6. ts=2020-02-27T23:10:33Z level=info msg="Version of operator-sdk: v0.15.2"

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 operator-sdk run local, you can use the --operator-flags flag to pass additional flags to your operator, including the zap flags. For example:

  1. $ operator-sdk run local --operator-flags="--zap-level=debug --zap-encoder=console"`

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. For example:

  1. apiVersion: apps/v1
  2. kind: Deployment
  3. metadata:
  4. name: memcached-operator
  5. spec:
  6. replicas: 1
  7. selector:
  8. matchLabels:
  9. name: memcached-operator
  10. template:
  11. metadata:
  12. labels:
  13. name: memcached-operator
  14. spec:
  15. serviceAccountName: memcached-operator
  16. containers:
  17. - name: memcached-operator
  18. # Replace this with the built image name
  19. image: REPLACE_IMAGE
  20. command:
  21. - memcached-operator
  22. args:
  23. - "--zap-level=debug"
  24. - "--zap-encoder=console"
  25. imagePullPolicy: Always
  26. env:
  27. - name: WATCH_NAMESPACE
  28. valueFrom:
  29. fieldRef:
  30. fieldPath: metadata.namespace
  31. - name: POD_NAME
  32. valueFrom:
  33. fieldRef:
  34. fieldPath: metadata.name
  35. - name: OPERATOR_NAME
  36. value: "memcached-operator"

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
  2. import (
  3. logf "sigs.k8s.io/controller-runtime/pkg/log"
  4. )
  5. // Set a global logger for the memcached package. Each log record produced
  6. // by this logger will have an identifier containing "controller_memcached".
  7. // These names are hierarchical; the name attached to memcached log statements
  8. // will be "operator-sdk.controller_memcached" because SDKLog has name
  9. // "operator-sdk".
  10. var log = logf.Log.WithName("controller_memcached")
  11. func (r *ReconcileMemcached) Reconcile(request reconcile.Request) (reconcile.Result, error) {
  12. // Create a logger for Reconcile() that includes "Request.Namespace"
  13. // and "Request.Name" in each log record from this log statement.
  14. reqLogger := log.WithValues("Request.Namespace", request.Namespace, "Request.Name", request.Name)
  15. reqLogger.Info("Reconciling Memcached.")
  16. memcached := &cachev1alpha1.Memcached{}
  17. err := r.client.Get(context.TODO(), request.NamespacedName, memcached)
  18. if err != nil {
  19. if errors.IsNotFound(err) {
  20. reqLogger.Info("Memcached resource not found. Ignoring since object must be deleted.")
  21. return reconcile.Result{}, nil
  22. }
  23. return reconcile.Result{}, err
  24. }
  25. found := &appsv1.Deployment{}
  26. err = r.client.Get(context.TODO(), types.NamespacedName{Name: memcached.Name, Namespace: memcached.Namespace}, found)
  27. if err != nil {
  28. if errors.IsNotFound(err) {
  29. dep := r.deploymentForMemcached(memcached)
  30. // Include "Deployment.Namespace" and "Deployment.Name" in records
  31. // produced by this particular log statement. "Request.Namespace" and
  32. // "Request.Name" will also be included from reqLogger.
  33. reqLogger.Info("Creating a new Deployment", "Deployment.Namespace", dep.Namespace, "Deployment.Name", dep.Name)
  34. err = r.client.Create(context.TODO(), dep)
  35. if err != nil {
  36. // Include the error in records produced by this log statement.
  37. reqLogger.Error(err, "Failed to create new Deployment", "Deployment.Namespace", dep.Namespace, "Deployment.Name", dep.Name)
  38. return reconcile.Result{}, err
  39. }
  40. }
  41. return reconcile.Result{}, err
  42. }
  43. ...
  44. }

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

  1. 2018-11-08T00:00:25.700Z ERROR operator-sdk.controller_memcached pkg/controller/memcached/memcached_controller.go:118 Failed to create new Deployment {"Request.Namespace", "memcached", "Request.Name", "memcached-operator", "Deployment.Namespace", "memcached", "Deployment.Name", "memcached-operator"}

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 cmd/manager/main.go, and add your own. Note that removing logr setup code will prevent controller-runtime from logging.

Last modified June 16, 2020: Switch over to new CLI and deprecate `operator-sdk new —type=go` (#3190) (e128b9e5)