Skip to content

Latest commit

 

History

History
169 lines (124 loc) · 6.34 KB

TMP-LOGGING.md

File metadata and controls

169 lines (124 loc) · 6.34 KB
Raw

Logging Guidelines

controller-runtime uses a kind of logging called structured logging. If you've used a library like Zap or logrus before, you'll be familiar with the concepts we use. If you've only used a logging library like the "log" package (in the Go standard library) or "glog" (in Kubernetes), you'll need to adjust how you think about logging a bit.

Getting Started With Structured Logging

With structured logging, we associate a constant log message with some variable key-value pairs. For instance, suppose we wanted to log that we were starting reconciliation on a pod. In the Go standard library logger, we might write:

log.Printf("starting reconciliation for pod %s/%s", podNamespace, podName)

In controller-runtime, we'd instead write:

logger.Info("starting reconciliation", "pod", req.NamespacedName)

or even write

func (r *Reconciler) Reconcile(req reconcile.Request) (reconcile.Response, error) {
    logger := logger.WithValues("pod", req.NamespacedName)
    // do some stuff
    logger.Info("starting reconciliation")
}

Notice how we've broken out the information that we want to convey into a constant message ("starting reconciliation") and some key-value pairs that convey variable information ("pod", req.NamespacedName). We've there-by added "structure" to our logs, which makes them easier to save and search later, as well as correlate with metrics and events.

All of controller-runtime's logging is done via logr, a generic interface for structured logging. You can use whichever logging library you want to implement the actual mechanics of the logging. controller-runtime provides some helpers to make it easy to use Zap as the implementation.

You can configure the logging implementation using "sigs.k8s.io/controller-runtime/pkg/log".SetLogger. That package also contains the convenience functions for setting up Zap.

You can get a handle to the "root" logger using "sigs.k8s.io/controller-runtime/pkg/log".Log, and can then call WithName to create individual named loggers. You can call WithName repeatedly to chain names together:

logger := log.Log.WithName("controller").WithName("replicaset")
// in reconcile...
logger = logger.WithValues("replicaset", req.NamespacedName)
// later on in reconcile...
logger.Info("doing things with pods", "pod", newPod)

As seen above, you can also call WithValue to create a new sub-logger that always attaches some key-value pairs to a logger.

Finally, you can use V(1) to mark a particular log line as "debug" logs:

logger.V(1).Info("this is particularly verbose!", "state of the world",
allKubernetesObjectsEverywhere)

While it's possible to use higher log levels, it's recommended that you stick with V(1) or V(0) (which is equivalent to not specifying V), and then filter later based on key-value pairs or messages; different numbers tend to lose meaning easily over time, and you'll be left wondering why particular logs lines are at V(5) instead of V(7).

Logging errors

Errors should always be logged with log.Error, which allows logr implementations to provide special handling of errors (for instance, providing stack traces in debug mode).

It's acceptable to log call log.Error with a nil error object. This conveys that an error occurred in some capacity, but that no actual error object was involved.

Errors returned by the Reconcile implementation of the Reconciler interface are commonly logged as a Reconciler error. It's a developer choice to create an additional error log in the Reconcile implementation so a more specific file name and line for the error are returned.

Logging messages

  • Don't put variable content in your messages -- use key-value pairs for that. Never use fmt.Sprintf in your message.

  • Try to match the terminology in your messages with your key-value pairs -- for instance, if you have a key-value pairs api version, use the term APIVersion instead of GroupVersion in your message.

Logging Kubernetes Objects

Kubernetes objects should be logged directly, like log.Info("this is a Kubernetes object", "pod", somePod). controller-runtime provides a special encoder for Zap that will transform Kubernetes objects into name, namespace, apiVersion, kind objects, when available and not in development mode. Other logr implementations should implement similar logic.

Logging Structured Values (Key-Value pairs)

  • Use lower-case, space separated keys. For example object for objects, api version for APIVersion

  • Be consistent across your application, and with controller-runtime when possible.

  • Try to be brief but descriptive.

  • Match terminology in keys with terminology in the message.

  • Be careful logging non-Kubernetes objects verbatim if they're very large.

Groups, Versions, and Kinds

  • Kinds should not be logged alone (they're meaningless alone). Use a GroupKind object to log them instead, or a GroupVersionKind when version is relevant.

  • If you need to log an API version string, use api version as the key (formatted as with a GroupVersion, or as received directly from API discovery).

Objects and Types

  • If code works with a generic Kubernetes runtime.Object, use the object key. For specific objects, prefer the resource name as the key (e.g. pod for v1.Pod objects).

  • For non-Kubernetes objects, the object key may also be used, if you accept a generic interface.

  • When logging a raw type, log it using the type key, with a value of fmt.Sprintf("%T", typ)

  • If there's specific context around a type, the key may be more specific, but should end with type -- for instance, OwnerType should be logged as owner in the context of log.Error(err, "Could not get ObjectKinds for OwnerType", owner type, fmt.Sprintf("%T")). When possible, favor communicating kind instead.

Multiple things

  • When logging multiple things, simply pluralize the key.

controller-runtime Specifics

  • Reconcile requests should be logged as request, although normal code should favor logging the key.

  • Reconcile keys should be logged as with the same key as if you were logging the object directly (e.g. log.Info("reconciling pod", "pod", req.NamespacedName)). This ends up having a similar effect to logging the object directly.