Contextual Logging in Kubernetes

The Structured Logging Working Group has added new capabilities to the logging infrastructure in Kubernetes. This blog post explains how developers can take advantage of those to make log output more useful and how they can get involved with improving Kubernetes.

Structured logging

The goal of structured logging is to replace C-style formatting and the resulting opaque log strings with log entries that have a well-defined syntax for storing message and parameters separately, for example as a JSON struct.

When using the traditional klog text output format for structured log calls, strings were originally printed with \n escape sequences, except when embedded inside a struct. For structs, log entries could still span multiple lines, with no clean way to split the log stream into individual entries:

I1112 14:06:35.783529  328441 structured_logging.go:51] "using InfoS" longData={Name:long Data:Multiple
lines
with quite a bit
of text. internal:0}
I1112 14:06:35.783549  328441 structured_logging.go:52] "using InfoS with\nthe message across multiple lines" int=1 stringData="long: Multiple\nlines\nwith quite a bit\nof text." str="another value"

Now, the < and > markers along with indentation are used to ensure that splitting at a klog header at the start of a line is reliable and the resulting output is human-readable:

I1126 10:31:50.378204  121736 structured_logging.go:59] "using InfoS" longData=<
 {Name:long Data:Multiple
 lines
 with quite a bit
 of text. internal:0}
 >
I1126 10:31:50.378228  121736 structured_logging.go:60] "using InfoS with\nthe message across multiple lines" int=1 stringData=<
 long: Multiple
 lines
 with quite a bit
 of text.
 > str="another value"

Note that the log message itself is printed with quoting. It is meant to be a fixed string that identifies a log entry, so newlines should be avoided there.

Before Kubernetes 1.24, some log calls in kube-scheduler still used klog.Info for multi-line strings to avoid the unreadable output. Now all log calls have been updated to support structured logging.

Contextual logging

Contextual logging is based on the go-logr API. The key idea is that libraries are passed a logger instance by their caller and use that for logging instead of accessing a global logger. The binary decides about the logging implementation, not the libraries. The go-logr API is designed around structured logging and supports attaching additional information to a logger.

This enables additional use cases:

• The caller can attach additional information to a logger:
• WithName adds a prefix
• WithValues adds key/value pairs
• When passing this extended logger into a function and a function uses it instead of the global logger, the additional information is then included in all log entries, without having to modify the code that generates the log entries. This is useful in highly parallel applications where it can become hard to identify all log entries for a certain operation because the output from different operations gets interleaved.
• When running unit tests, log output can be associated with the current test. Then when a test fails, only the log output of the failed test gets shown by go test. That output can also be more verbose by default because it will not get shown for successful tests. Tests can be run in parallel without interleaving their output.

One of the design decisions for contextual logging was to allow attaching a logger as value to a context.Context. Since the logger encapsulates all aspects of the intended logging for the call, it is part of the context and not just using it. A practical advantage is that many APIs already have a ctx parameter or adding one has additional advantages, like being able to get rid of context.TODO() calls inside the functions.

Another decision was to not break compatibility with klog v2:

• Libraries that use the traditional klog logging calls in a binary that has set up contextual logging will work and log through the logging backend chosen by the binary. However, such log output will not include the additional information and will not work well in unit tests, so libraries should be modified to support contextual logging. The migration guide for structured logging has been extended to also cover contextual logging.
• When a library supports contextual logging and retrieves a logger from its context, it will still work in a binary that does not initialize contextual logging because it will get a logger that logs through klog.

In Kubernetes 1.24, contextual logging is a new alpha feature with ContextualLogging as feature gate. When disabled (the default), the new klog API calls for contextual logging (see below) become no-ops to avoid performance or functional regressions.

No Kubernetes component has been converted yet. An example program in the Kubernetes repository demonstrates how to enable contextual logging in a binary and how the output depends on the binary’s parameters:

$ cd $GOPATH/src/k8s.io/kubernetes/staging/src/k8s.io/component-base/logs/example/cmd/
$ go run . --help
...
      --feature-gates mapStringBool  A set of key=value pairs that describe feature gates for alpha/experimental features. Options are:
                                     AllAlpha=true|false (ALPHA - default=false)
                                     AllBeta=true|false (BETA - default=false)
                                     ContextualLogging=true|false (ALPHA - default=false)
$ go run . --feature-gates ContextualLogging=true
...
I0404 18:00:02.916429  451895 logger.go:94] "example/myname: runtime" foo="bar" duration="1m0s"
I0404 18:00:02.916447  451895 logger.go:95] "example: another runtime" foo="bar" duration="1m0s"

The example prefix and foo="bar" were added by the caller of the function which logs the runtime message and duration="1m0s" value.

The sample code for klog includes an example for a unit test with per-test output.