-
Notifications
You must be signed in to change notification settings - Fork 152
Commit
This commit does not belong to any branch on this repository, and may belong to a fork outside of the repository.
Kubernetes 1.24: contextual logging blog post
Contextual logging is an enhancement that landed as alpha in Kubernetes 1.24. Because it targets primarily developers of Kubernetes at this point, publishing it under https://k8s.dev/blog on the same day as it also gets published on the main blog (see kubernetes/website#32656) makes sense.
- Loading branch information
Showing
1 changed file
with
256 additions
and
0 deletions.
There are no files selected for viewing
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Original file line number | Diff line number | Diff line change |
---|---|---|
@@ -0,0 +1,256 @@ | ||
--- | ||
layout: blog | ||
title: "Contextual Logging in Kubernetes 1.24" | ||
date: 2022-05-25 | ||
slug: contextual-logging | ||
--- | ||
|
||
**Authors:** Patrick Ohly (Intel) | ||
|
||
The [Structured Logging Working | ||
Group](https://github.com/kubernetes/community/blob/master/wg-structured-logging/README.md) | ||
has added new capabilities to the logging infrastructure in Kubernetes | ||
1.24. 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 for [structured | ||
logging](https://github.com/kubernetes/enhancements/blob/master/keps/sig-instrumentation/1602-structured-logging/README.md) | ||
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 `<` and `>` markers and indention are used to ensure that splitting at a | ||
klog header at the start of a line is reliable and the output remains readable | ||
for humans: | ||
|
||
``` | ||
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 kube-scheduler has | ||
been converted completely to structured logging. | ||
|
||
## Contextual Logging | ||
|
||
[Contextual | ||
logging](https://github.com/kubernetes/enhancements/blob/master/keps/sig-instrumentation/3077-contextual-logging/README.md) | ||
is based on the [go-logr | ||
API](https://github.com/go-logr/logr#a-minimal-logging-api-for-go). 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 a prefix | ||
([`WithName`](https://pkg.go.dev/github.com/go-logr/logr#Logger.WithName)) | ||
and additional values | ||
([`WithValues`](https://pkg.go.dev/github.com/go-logr/logr#Logger.WithValues)) | ||
to the logger that it passes into a function. This 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`. Because 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 get modified to support contextual logging. The [migration | ||
guide](https://github.com/kubernetes/community/blob/master/contributors/devel/sig-instrumentation/migration-to-structured-logging.md) | ||
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](https://github.com/kubernetes/kubernetes/blob/v1.24.0-beta.0/staging/src/k8s.io/component-base/logs/example/cmd/logger.go) | ||
in the Kubernetes repository demonstrates how to enable contextual logging in a | ||
binary and how the output depends on the binary's parameters: | ||
|
||
```console | ||
$ 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. | ||
|
||
An example for a unit test with per-test output is [included in | ||
klog](https://github.com/kubernetes/klog/blob/v2.60.1/ktesting/example/example_test.go). | ||
|
||
## klog enhancements | ||
|
||
### Contextual logging API | ||
|
||
The following calls manage the lookup of a logger: | ||
|
||
- [`FromContext`](https://pkg.go.dev/k8s.io/klog/v2#FromContext): from a | ||
`context` parameter, with fallback to the global logger | ||
- [`Background`](https://pkg.go.dev/k8s.io/klog/v2#Background): the global | ||
fallback, with no intention to support contextual logging | ||
- [`TODO`](https://pkg.go.dev/k8s.io/klog/v2#TODO): the global fallback, but | ||
only as a temporary solution until the function gets extended to accept | ||
a logger through its parameters | ||
- [`SetLoggerWithOptions`](https://pkg.go.dev/k8s.io/klog/v2#SetLoggerWithOptions): | ||
changes the fallback logger; when called with | ||
[`ContextualLogger(true)`](https://pkg.go.dev/k8s.io/klog/v2#ContextualLogger), | ||
the logger is ready to be called directly, in which case logging will be done | ||
without going through klog | ||
|
||
To support the feature gate mechanism in Kubernetes, klog has wrapper calls for | ||
the corresponding go-logr calls and a global boolean controlling their behavior: | ||
|
||
- [`LoggerWithName`](https://pkg.go.dev/k8s.io/klog/v2#LoggerWithName) | ||
- [`LoggerWithValues`](https://pkg.go.dev/k8s.io/klog/v2#LoggerWithValues) | ||
- [`NewContext`](https://pkg.go.dev/k8s.io/klog/v2#NewContext) | ||
- [`EnableContextualLogging`](https://pkg.go.dev/k8s.io/klog/v2#EnableContextualLogging) | ||
|
||
Usage of those functions in Kubernetes code is enforced with a linter | ||
check. The klog default for contextual logging is to enable the functionality | ||
because it is considered stable in klog. It is only in Kubernetes binaries | ||
where that default gets overridden and (in some binaries) controlled via the | ||
`--feature-gate` parameter. | ||
|
||
### ktesting logger | ||
|
||
The new [ktesting](https://pkg.go.dev/k8s.io/klog/v2@v2.60.1/ktesting) package | ||
implements logging through `testing.T` using klog's text output format. It has | ||
a [single API | ||
call](https://pkg.go.dev/k8s.io/klog/v2@v2.60.1/ktesting#NewTestContext) for | ||
instrumenting a test case and [support for command line | ||
flags](https://pkg.go.dev/k8s.io/klog/v2@v2.60.1/ktesting/init). | ||
|
||
### klogr | ||
|
||
[`klog/klogr`](https://pkg.go.dev/k8s.io/klog/v2@v2.60.1/klogr) continues to be | ||
supported and it's default behavior is unchanged: it formats structured log | ||
entries using its own, custom format and prints the result via klog. | ||
|
||
However, this usage is discouraged because that format is neither | ||
machine-readable (in contrast to real JSON output as produced by zapr, the | ||
go-logr implementation used by Kubernetes) nor human-friendly (in contrast to | ||
the klog text format). | ||
|
||
Instead, a klogr instance should be created with | ||
[`WithFormat(FormatKlog)`](https://pkg.go.dev/k8s.io/klog/v2@v2.60.1/klogr#WithFormat) | ||
which chooses the klog text format. A simpler construction method with the same | ||
result is the new | ||
[`klog.NewKlogr`](https://pkg.go.dev/k8s.io/klog/v2#NewKlogr). That is the | ||
logger that klog returns as fallback when nothing else is configured. | ||
|
||
### reusable output test | ||
|
||
A lot of go-logr implementations have very similar unit tests where they check | ||
the result of certain log calls. If a developer didn't know about certain | ||
caveats like for example a `String` function that panics when called, then it | ||
is likely that both the handling of such caveats and the unit test are missing. | ||
|
||
[`klog.test`](https://pkg.go.dev/k8s.io/klog/v2@v2.60.1/test) is a reusable set | ||
of test cases that can be applied to a go-logr implementation. | ||
|
||
### Output flushing | ||
|
||
klog used to start a goroutine unconditionally during `init` which flushed | ||
buffered data at a hard-coded interval. Now that goroutine is only started on | ||
demand (i.e. when writing to files with buffering) and can be controlled with | ||
[`StopFlushDaemon`](https://pkg.go.dev/k8s.io/klog/v2#StopFlushDaemon) and | ||
[`StartFlushDaemon`](https://pkg.go.dev/k8s.io/klog/v2#StartFlushDaemon). | ||
|
||
When a go-logr implementation buffers data, flushing that data can be | ||
integrated into [`klog.Flush`](https://pkg.go.dev/k8s.io/klog/v2#Flush) by | ||
registering the logger with the | ||
[`FlushLogger`](https://pkg.go.dev/k8s.io/klog/v2#FlushLogger) option. | ||
|
||
### Various other changes | ||
|
||
For a description of all other enhancements see in the [release | ||
notes](https://github.com/kubernetes/klog/releases). | ||
|
||
## logcheck | ||
|
||
Originally designed as a linter for structured log calls, the | ||
[`logcheck`](https://github.com/kubernetes/klog/tree/main/hack/tools/logcheck) | ||
tool has been enhanced to support also contextual logging and traditional klog | ||
log calls. These enhanced checks already found bugs in Kubernetes, like calling | ||
`klog.Info` instead of `klog.Infof` with a format string and parameters. | ||
|
||
It can be included as a plugin in a `golangci-lint` invocation, which is how | ||
[Kubernetes uses it | ||
now](https://github.com/kubernetes/kubernetes/commit/17e3c555c5115f8c9176bae10ba45baa04d23a7b), | ||
or get invoked stand-alone. | ||
|
||
We are in the process of moving the tool into a [new | ||
repository](https://github.com/kubernetes/klog/issues/312) because it isn't | ||
really related to klog and its releases should be tracked and tagged properly. | ||
|
||
## Next steps | ||
|
||
The [Structured Logging WG](https://github.com/kubernetes/community/tree/master/wg-structured-logging) | ||
is always looking for new contributors. The migration | ||
away from C-style logging is now going to target structured, contextual logging | ||
in one step to reduce the overall code churn and number of PRs. Changing log | ||
calls is good first contribution to Kubernetes and an opportunity to get to | ||
know code in various different areas. |