Skip to content

Commit e475891

Browse files
k8s-ci-robotk8s-ci-robot
authored
Merge pull request #32656 from pohly/kubernetes-1.24-contextual-logging
contextual logging blog post
2 parents 76ec92c + 1ec1d50 commit e475891

File tree

1 file changed

+251
-0
lines changed
  • content/en/blog/_posts/2022-05-25-contextual-logging

1 file changed

+251
-0
lines changed

‎content/en/blog/_posts/2022-05-25-contextual-logging/index.md

Lines changed: 251 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,251 @@
1+
---
2+
layout: blog
3+
title: "Contextual Logging in Kubernetes 1.24"
4+
date: 2022-05-25
5+
slug: contextual-logging
6+
canonicalUrl: https://kubernetes.dev/blog/2022/05/25/contextual-logging/
7+
---
8+
9+
**Authors:** Patrick Ohly (Intel)
10+
11+
The [Structured Logging Working
12+
Group](https://github.com/kubernetes/community/blob/master/wg-structured-logging/README.md)
13+
has added new capabilities to the logging infrastructure in Kubernetes
14+
1.24. This blog post explains how developers can take advantage of those to
15+
make log output more useful and how they can get involved with improving Kubernetes.
16+
17+
## Structured logging
18+
19+
The goal of [structured
20+
logging](https://github.com/kubernetes/enhancements/blob/master/keps/sig-instrumentation/1602-structured-logging/README.md)
21+
is to replace C-style formatting and the resulting opaque log strings with log
22+
entries that have a well-defined syntax for storing message and parameters
23+
separately, for example as a JSON struct.
24+
25+
When using the traditional klog text output format for structured log calls,
26+
strings were originally printed with `\n` escape sequences, except when
27+
embedded inside a struct. For structs, log entries could still span multiple
28+
lines, with no clean way to split the log stream into individual entries:
29+
30+
```
31+
I1112 14:06:35.783529 328441 structured_logging.go:51] "using InfoS" longData={Name:long Data:Multiple
32+
lines
33+
with quite a bit
34+
of text. internal:0}
35+
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"
36+
```
37+
38+
Now, the `<` and `>` markers along with indentation are used to ensure that splitting at a
39+
klog header at the start of a line is reliable and the resulting output is human-readable:
40+
41+
```
42+
I1126 10:31:50.378204 121736 structured_logging.go:59] "using InfoS" longData=<
43+
{Name:long Data:Multiple
44+
lines
45+
with quite a bit
46+
of text. internal:0}
47+
>
48+
I1126 10:31:50.378228 121736 structured_logging.go:60] "using InfoS with\nthe message across multiple lines" int=1 stringData=<
49+
long: Multiple
50+
lines
51+
with quite a bit
52+
of text.
53+
> str="another value"
54+
```
55+
56+
Note that the log message itself is printed with quoting. It is meant to be a
57+
fixed string that identifies a log entry, so newlines should be avoided there.
58+
59+
Before Kubernetes 1.24, some log calls in kube-scheduler still used `klog.Info`
60+
for multi-line strings to avoid the unreadable output. Now all log calls have
61+
been updated to support structured logging.
62+
63+
## Contextual logging
64+
65+
[Contextual logging](https://github.com/kubernetes/enhancements/blob/master/keps/sig-instrumentation/3077-contextual-logging/README.md)
66+
is based on the [go-logr API](https://github.com/go-logr/logr#a-minimal-logging-api-for-go). The key
67+
idea is that libraries are passed a logger instance by their caller and use
68+
that for logging instead of accessing a global logger. The binary decides about
69+
the logging implementation, not the libraries. The go-logr API is designed
70+
around structured logging and supports attaching additional information to a
71+
logger.
72+
73+
This enables additional use cases:
74+
75+
- The caller can attach additional information to a logger:
76+
- [`WithName`](https://pkg.go.dev/github.com/go-logr/logr#Logger.WithName) adds a prefix
77+
- [`WithValues`](https://pkg.go.dev/github.com/go-logr/logr#Logger.WithValues) adds key/value pairs
78+
79+
When passing this extended logger into a function and a function uses it
80+
instead of the global logger, the additional information is
81+
then included in all log entries, without having to modify the code that
82+
generates the log entries. This is useful in highly parallel applications
83+
where it can become hard to identify all log entries for a certain operation
84+
because the output from different operations gets interleaved.
85+
86+
- When running unit tests, log output can be associated with the current test.
87+
Then when a test fails, only the log output of the failed test gets shown
88+
by `go test`. That output can also be more verbose by default because it
89+
will not get shown for successful tests. Tests can be run in parallel
90+
without interleaving their output.
91+
92+
One of the design decisions for contextual logging was to allow attaching a
93+
logger as value to a `context.Context`. Since the logger encapsulates all
94+
aspects of the intended logging for the call, it is *part* of the context and
95+
not just *using* it. A practical advantage is that many APIs already have a
96+
`ctx` parameter or adding one has additional advantages, like being able to get
97+
rid of `context.TODO()` calls inside the functions.
98+
99+
Another decision was to not break compatibility with klog v2:
100+
101+
- Libraries that use the traditional klog logging calls in a binary that has
102+
set up contextual logging will work and log through the logging backend
103+
chosen by the binary. However, such log output will not include the
104+
additional information and will not work well in unit tests, so libraries
105+
should be modified to support contextual logging. The [migration guide](https://github.com/kubernetes/community/blob/master/contributors/devel/sig-instrumentation/migration-to-structured-logging.md)
106+
for structured logging has been extended to also cover contextual logging.
107+
108+
- When a library supports contextual logging and retrieves a logger from its
109+
context, it will still work in a binary that does not initialize contextual
110+
logging because it will get a logger that logs through klog.
111+
112+
In Kubernetes 1.24, contextual logging is a new alpha feature with
113+
`ContextualLogging` as feature gate. When disabled (the default), the new klog
114+
API calls for contextual logging (see below) become no-ops to avoid performance
115+
or functional regressions.
116+
117+
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)
118+
in the Kubernetes repository demonstrates how to enable contextual logging in a
119+
binary and how the output depends on the binary's parameters:
120+
121+
```console
122+
$ cd $GOPATH/src/k8s.io/kubernetes/staging/src/k8s.io/component-base/logs/example/cmd/
123+
$ go run . --help
124+
...
125+
--feature-gates mapStringBool A set of key=value pairs that describe feature gates for alpha/experimental features. Options are:
126+
AllAlpha=true|false (ALPHA - default=false)
127+
AllBeta=true|false (BETA - default=false)
128+
ContextualLogging=true|false (ALPHA - default=false)
129+
$ go run . --feature-gates ContextualLogging=true
130+
...
131+
I0404 18:00:02.916429 451895 logger.go:94] "example/myname: runtime" foo="bar" duration="1m0s"
132+
I0404 18:00:02.916447 451895 logger.go:95] "example: another runtime" foo="bar" duration="1m0s"
133+
```
134+
135+
The `example` prefix and `foo="bar"` were added by the caller of the function
136+
which logs the `runtime` message and `duration="1m0s"` value.
137+
138+
The sample code for klog includes an
139+
[example](https://github.com/kubernetes/klog/blob/v2.60.1/ktesting/example/example_test.go)
140+
for a unit test with per-test output.
141+
142+
## klog enhancements
143+
144+
### Contextual logging API
145+
146+
The following calls manage the lookup of a logger:
147+
148+
[`FromContext`](https://pkg.go.dev/k8s.io/klog/v2#FromContext)
149+
: from a `context` parameter, with fallback to the global logger
150+
151+
[`Background`](https://pkg.go.dev/k8s.io/klog/v2#Background)
152+
: the global fallback, with no intention to support contextual logging
153+
154+
[`TODO`](https://pkg.go.dev/k8s.io/klog/v2#TODO)
155+
: the global fallback, but only as a temporary solution until the function gets extended to accept
156+
a logger through its parameters
157+
158+
[`SetLoggerWithOptions`](https://pkg.go.dev/k8s.io/klog/v2#SetLoggerWithOptions)
159+
: changes the fallback logger; when called with [`ContextualLogger(true)`](https://pkg.go.dev/k8s.io/klog/v2#ContextualLogger),
160+
the logger is ready to be called directly, in which case logging will be done
161+
without going through klog
162+
163+
To support the feature gate mechanism in Kubernetes, klog has wrapper calls for
164+
the corresponding go-logr calls and a global boolean controlling their behavior:
165+
166+
- [`LoggerWithName`](https://pkg.go.dev/k8s.io/klog/v2#LoggerWithName)
167+
- [`LoggerWithValues`](https://pkg.go.dev/k8s.io/klog/v2#LoggerWithValues)
168+
- [`NewContext`](https://pkg.go.dev/k8s.io/klog/v2#NewContext)
169+
- [`EnableContextualLogging`](https://pkg.go.dev/k8s.io/klog/v2#EnableContextualLogging)
170+
171+
Usage of those functions in Kubernetes code is enforced with a linter
172+
check. The klog default for contextual logging is to enable the functionality
173+
because it is considered stable in klog. It is only in Kubernetes binaries
174+
where that default gets overridden and (in some binaries) controlled via the
175+
`--feature-gate` parameter.
176+
177+
### ktesting logger
178+
179+
The new [ktesting](https://pkg.go.dev/k8s.io/klog/[email protected]/ktesting) package
180+
implements logging through `testing.T` using klog's text output format. It has
181+
a [single API call](https://pkg.go.dev/k8s.io/klog/[email protected]/ktesting#NewTestContext) for
182+
instrumenting a test case and [support for command line flags](https://pkg.go.dev/k8s.io/klog/[email protected]/ktesting/init).
183+
184+
### klogr
185+
186+
[`klog/klogr`](https://pkg.go.dev/k8s.io/klog/[email protected]/klogr) continues to be
187+
supported and it's default behavior is unchanged: it formats structured log
188+
entries using its own, custom format and prints the result via klog.
189+
190+
However, this usage is discouraged because that format is neither
191+
machine-readable (in contrast to real JSON output as produced by zapr, the
192+
go-logr implementation used by Kubernetes) nor human-friendly (in contrast to
193+
the klog text format).
194+
195+
Instead, a klogr instance should be created with
196+
[`WithFormat(FormatKlog)`](https://pkg.go.dev/k8s.io/klog/[email protected]/klogr#WithFormat)
197+
which chooses the klog text format. A simpler construction method with the same
198+
result is the new
199+
[`klog.NewKlogr`](https://pkg.go.dev/k8s.io/klog/v2#NewKlogr). That is the
200+
logger that klog returns as fallback when nothing else is configured.
201+
202+
### Reusable output test
203+
204+
A lot of go-logr implementations have very similar unit tests where they check
205+
the result of certain log calls. If a developer didn't know about certain
206+
caveats like for example a `String` function that panics when called, then it
207+
is likely that both the handling of such caveats and the unit test are missing.
208+
209+
[`klog.test`](https://pkg.go.dev/k8s.io/klog/[email protected]/test) is a reusable set
210+
of test cases that can be applied to a go-logr implementation.
211+
212+
### Output flushing
213+
214+
klog used to start a goroutine unconditionally during `init` which flushed
215+
buffered data at a hard-coded interval. Now that goroutine is only started on
216+
demand (i.e. when writing to files with buffering) and can be controlled with
217+
[`StopFlushDaemon`](https://pkg.go.dev/k8s.io/klog/v2#StopFlushDaemon) and
218+
[`StartFlushDaemon`](https://pkg.go.dev/k8s.io/klog/v2#StartFlushDaemon).
219+
220+
When a go-logr implementation buffers data, flushing that data can be
221+
integrated into [`klog.Flush`](https://pkg.go.dev/k8s.io/klog/v2#Flush) by
222+
registering the logger with the
223+
[`FlushLogger`](https://pkg.go.dev/k8s.io/klog/v2#FlushLogger) option.
224+
225+
### Various other changes
226+
227+
For a description of all other enhancements see in the [release notes](https://github.com/kubernetes/klog/releases).
228+
229+
## logcheck
230+
231+
Originally designed as a linter for structured log calls, the
232+
[`logcheck`](https://github.com/kubernetes/klog/tree/788efcdee1e9be0bfbe5b076343d447314f2377e/hack/tools/logcheck)
233+
tool has been enhanced to support also contextual logging and traditional klog
234+
log calls. These enhanced checks already found bugs in Kubernetes, like calling
235+
`klog.Info` instead of `klog.Infof` with a format string and parameters.
236+
237+
It can be included as a plugin in a `golangci-lint` invocation, which is how
238+
[Kubernetes uses it now](https://github.com/kubernetes/kubernetes/commit/17e3c555c5115f8c9176bae10ba45baa04d23a7b),
239+
or get invoked stand-alone.
240+
241+
We are in the process of [moving the tool](https://github.com/kubernetes/klog/issues/312) into a new repository because it isn't
242+
really related to klog and its releases should be tracked and tagged properly.
243+
244+
## Next steps
245+
246+
The [Structured Logging WG](https://github.com/kubernetes/community/tree/master/wg-structured-logging)
247+
is always looking for new contributors. The migration
248+
away from C-style logging is now going to target structured, contextual logging
249+
in one step to reduce the overall code churn and number of PRs. Changing log
250+
calls is good first contribution to Kubernetes and an opportunity to get to
251+
know code in various different areas.

0 commit comments

Comments
 (0)