Skip to content

Commit

Permalink
Add instructions for structured logging migration
Browse files Browse the repository at this point in the history 
Co-authored-by: Md. Tahsin Rahman <[email protected]>
  • Loading branch information
@serathius @tahsinrahman
serathius and tahsinrahman committed Jun 3, 2020
1 parent 287d14a commit 5e71635
Showing 1 changed file with 383 additions and 0 deletions.
383 changes: 383 additions & 0 deletions contributors/devel/sig-instrumentation/migration-to-structured-logging.md
View file
Original file line number Diff line number Diff line change
@@ -0,0 +1,383 @@
# Structured Logging migration instructions

This document describes instructions for migration proposed by [Structured Logging KEP]. It describes new structured
functions introduced in `klog` (Kubernetes logging library) and how log calls should be changed to utilize new features.
This document was written for the initial migration of `kubernetes/kubernetes` repository proposed for Alpha stage, but
should be applicable at later stages or for other projects using `klog` logging library.

[Structured Logging KEP]: https://github.com/kubernetes/enhancements/tree/master/keps/sig-instrumentation/1602-structured-logging

## Goal of Alpha migration

The first step is to introduce structure to the high percentage of logs generated in Kubernetes by changing only a
small number of logs API calls. Based on criteria described in the [selecting most important logs] section, the selected
22 log calls are estimated to impact 99.9% of log volume. The up to date list of these log calls is provided in the
[Enhancement Issue].

[Enhancement Issue]: https://github.com/kubernetes/enhancements/issues/1602
[selecting most important logs]: https://github.com/kubernetes/enhancements/tree/master/keps/sig-instrumentation/1602-structured-logging#selecting-most-important-logs

## Structured logging in Kubernetes

With this enhancement a set of new functions were added to `klog`. Structured logging functions the follow interface
based on [logr], which has a different design than other `klog` functions which are based on [glog]. It is recommended
to familiarize yourself with [logr].

[logr]: https://github.com/go-logr/logr
[glog]: https://github.com/golang/glog

Here are the prototypes of functions added to `klog` that will be utilized during migration:
```go
package klog

// InfoS structured logs to the INFO log.
// The msg argument used to add constant description to the log line.
// The key/value pairs would be join by "=" ; a newline is always appended.
//
// Examples:
// >> klog.InfoS("Pod status updated", "pod", klog.KObj(pod), "status", "ready")
// output:
// >> I1025 00:15:15.525108 1 controller_utils.go:116] "Pod status updated" pod="kube-system/kubedns" status="ready"
func InfoS(msg string, keysAndValues ...interface{})

// ErrorS structured logs to the ERROR, WARNING, and INFO logs.
// the err argument used as "err" field of log line.
// The msg argument used to add constant description to the log line.
// The key/value pairs would be join by "=" ; a newline is always appended.
//
// Examples:
// >> klog.ErrorS(err, "Failed to update pod status")
// output:
// >> E1025 00:15:15.525108 1 controller_utils.go:114] "Failed to update pod status" err="timeout"
func ErrorS(err error, msg string, keysAndValues ...interface{})

// KObj is used to create ObjectRef when logging information about Kubernetes objects
// Examples:
// >> klog.InfoS("Pod status updated", "pod", klog.KObj(pod), "status", "ready")
// output:
// >> I1025 00:15:15.525108 1 controller_utils.go:116] "Pod status updated" pod="kube-system/kubedns" status="ready"
func KObj(obj KMetadata) ObjectRef

// KRef is used to create ObjectRef when logging information about Kubernetes objects without access to metav1.Object
// Examples:
// >> klog.InfoS("Pod status updated", "pod", klog.KRef(podNamespace, podName), "status", "ready")
// output:
// >> I1025 00:15:15.525108 1 controller_utils.go:116] "Pod status updated" pod="kube-system/kubedns" status="ready"
func KRef(namespace, name string) ObjectRef

// ObjectRef represents a reference to a kubernetes object used for logging purpose
// In text logs it is serialized into "{namespace}/{name}" or "{name}" if namespace is empty
type ObjectRef struct {
Name string `json:"name"`
Namespace string `json:"namespace,omitempty"`
}

// KMetadata is a subset of the kubernetes k8s.io/apimachinery/pkg/apis/meta/v1.Object interface
// this interface may expand in the future, but will always be a subset of the
// kubernetes k8s.io/apimachinery/pkg/apis/meta/v1.Object interface
type KMetadata interface {
GetName() string
GetNamespace() string
}
```

## Migration

1. Change log functions to structured equivalent
1. Remove string formatting from log message
1. Name arguments
1. Use `klog.KObj` and `klog.KRef` for Kubernetes object references
1. Verify log output

## Change log functions to structured equivalent

Structured logging functions follow a different logging interface design than other functions in `klog`. They follow
minimal design from [logr] thus there is no one-to-one mapping.

Simplified mapping between functions:
* `klog.Infof`, `klog.Info`, `klog.Infoln`, `klog.InfoDepth` -> `klog.InfoS`
* `klog.V(N).Infof`, `klog.V(N).Info`, `klog.V(N).Infoln` -> `klog.V(N).InfoS`
* `klog.Warning`, `klog.Warningf`, `klog.Warningln`, `klog.WarningDepth` -> `klog.InfoS`
* `klog.Error`, `klog.Errorf`, `klog.Errorln`, `klog.ErrorDepth` -> `klog.ErrorS`
* `klog.Fatal`, `klog.Fatalf`, `klog.Fatalln`, `klog.FatalDepth` -> `klog.ErrorS`

### Removing Depth

Functions with depth (`klog.InfoDepth`, `klog.WarningDepth`, `klog.ErrorDepth`, `klog.FatalDepth`) are used to indicate
that the source of the log (added as metadata in log) is different than the invocation of logging library. This is
usually used when implementing logging util functions. As logr interface doesn't support depth, those functions should
return logging arguments instead of calling `klog` directly.

For example
```go
func Handle(w http.ReponseWriter, r *http.Request) {
logHTTPRequest(r)
handle(w, r)
}

func logHTTPRequest(r *http.Request) {
klog.InfoDepth(1, "Received HTTP %s request", r.Method)
}
```
should be replaced with
```go
func Handle(w http.ReponseWriter, r *http.Request) {
klog.Info("Received HTTP request", httpRequestLog(r)...)
handle(w, r)
}

func httpRequestLog(r *http.Request) []interface{} {
return []interface{}{
"verb", r.Method,
}
}

```

### Using ErrorS

With `klog` structured logging borrowing the interface from [logr] it also inherits it's differences in semantic of
error function. Logs generated by `ErrorS` command may be enhanced with additional debug information
(such as stack traces) or be additionally sent to special error recording tools. Errors should be used to indicate
unexpected behaviours in code, like unexpected errors returned by subroutine function calls.

Calling `ErrorS` with `nil` as error is semi-acceptable if there is error condition that deserves a stack trace at this
origin point. For expected errors (`errors` that can happen during routine operations) please consider using
`klog.InfoS` and pass error in `err` key instead.

### Replacing Fatal calls

Use of Fatal should be discouraged and it's not available in new functions. Instead of depending on the logger to exit
the process, you should call `os.Exit()` yourself.

## Remove string formatting from log message

With structured logging, log messages are no longer formatted, leaving argument marshalling up to the logging client
implementation. This allows messages to be a static description of event.

All string formatting (`%d`, `%v`, `%w`, `%s`) should be removed and log message string simplified.
Describing arguments in log messages is no longer needed and should be removed leaving only a description of what
happened.

Additionally we can improve messages to comply with good practices:
* Start from a capital letter.
* Do not end the message with a period.
* Use active voice. Use complete sentences when there is an acting subject ("A could not do B") or omit the subject if
the subject would be the program itself ("Could not do B").
* Use past tense ("Could not delete B" instead of "Cannot delete B")
* When referring to an object, state what type of object it is. ("Deleted pod" instead of "Deleted")

For example
```go
klog.Infof("delete pod %s with propagation policy %s", ...)
```
should be changed to
```go
klog.Infof("Deleted pod", ...)
```

Some logs are constructed solely from string formats. In those cases a message needs to be derived from the context of
the log call.

For example http access logs
```go
func LogHTTP(r *http.Request) {
klog.Infof("%s %s: (%v) %v%v%v [%s %s]", ...)
}
```
should be changed to
```go
func LogHTTP(r *http.Request) {
klog.InfoS("Received HTTP request", ...)
}
```

### Name arguments

Even though new structured logging functions have very similar function prototype `func (string, ...interface{})` it
has different meaning for variadic arguments. Instead of just passing arguments, now we are passing key value pairs of
argument name and argument value. This means when migrating a log call we need to add an additional string before each
argument, that will be used as it's name.

For example
```go
func LogHTTP(r *http.Request) {
klog.Infof("Received HTTP request, path: %s, method: %s", r.Path, r.Method)
}
```
should be changed to
```go
func LogHTTP(r *http.Request) {
klog.InfoS("Received HTTP request", "path", r.Path, "method", r.Method)
}
```

Names of arguments should use [lowerCamelCase] and be alphanumeric. Arguments names in one log call should be unique.
Names should be picked based on semantic meaning of value itself, not the context in which is used (log message should
imply the context). For example names like `status` should be used over (`desiredStatus`, `oldStatus`, `badStatus`) thus
allowing to query and join different log lines of the `status` field.

Kubernetes objects should be referenced using only their kind, no matter their api group or version. Example argument
names: `deployment`, `pod`, `node`, `replicaSet`. For objects of unknown type, is ok to log them under `object` key with
addition of `apiVersion` and `kind` fields describing the k8s object type.

In situations when we want to the log value of the same meaning twice (e.g. transition between state) it is ok to name
an additional argument based on context, but leaving one most current/correct value with canonical name.

Examples of keys (strongly suggested, will be extended when pattern emerge, no standard schema yet):
* `err` - error when using `klog.InfoS`. Used for expected errors that are not `klog.ErrorS`.
* `object` - reference to k8s objects of unknown type. Should be used with `kind` and `apiVersion`.
* `kind` - kind of k8s object of unknown type.
* `apiVersion` - API version of k8s object of unknown type.

Example:

```go
func ChangeStatus(newStatus, currentStatus string) {
err := changeStatus(newStatus)
if err != nil {
klog.ErrorS(err, "Failed changing status", "desiredStatus", newStatus, "status", currentStatus)
}
klog.InfoS("Changed status", "previousStatus", currentStatus, "status", newStatus)
}
```

[lowerCamelCase]: https://en.wiktionary.org/wiki/lowerCamelCase

### Use `klog.KObj` and `klog.KRef` for Kubernetes objects

As part of structured logging migration we want to ensure that kubernetes objects references are consistent within the
codebase. Two new utility functions were introduced to klog `klog.KObj` and `klog.KRef`. Any reference
(name, uid, namespace) to Kubernetes Object (Pod, Node, Deployment, CRD) should be rewritten to utilize those functions.
In situations when object `UID` is would be beneficial for log, it should be added as separate field with `UID` suffix.

For example
```go
func updatePod(pod *covev1.Pod) {
...
klog.Infof("Updated pod %s in namespace %s", pod.Name, pod.Namespace)
}
```
should be changed to
```go
func updatePod(pod *covev1.Pod) {
...
klog.InfoS("Updated pod", "pod", klog.KObj(pod))
}
```
And
```go
func updatePod(pod *covev1.Pod) {
...
klog.Infof("Updated pod with uid: %s", pod.Uid)
}
```
should be changed to
```go
func updatePod(pod *covev1.Pod) {
...
klog.InfoS("Updated pod", "pod", klog.KObj(pod), "podUID", pod.Uid)
}
```

`klog.KObj` requires passing a kubernetes object (struct implementing `metav1.Object` interface). In situations where
the object is not available, we can use `klog.KRef`. Still it is suggested to rewrite the code to use object pointer
instead of strings where possible.

```go
func updatePod(podName, podNamespace string) {
...
klog.InfoS("Updated pod", "pod", klog.KRef(podNamespace, podName))
}
```

For non-namespaced object we can pass empty string to namespace argument

```go
func updateNode(nodeName string) {
...
klog.InfoS("Updated node", "node", klog.KRef("", nodeName))
}
```

### Verify log output

With the introduction of structured functions log arguments will be formatted automatically instead of depending on the
caller. This means that we can remove the burden of picking the format by caller and ensure greater log consistency, but during
migration it's important to ensure that we avoid degradation of log quality. We should ensure that during migration we
preserve properties like:
* meaning of event described by log
* verbosity of stored information

PRs migrating logs should include examples of outputted logs before and after the change, thus helping reviewers
understand the impact of change.

Example code to compare [httplog.go#168](https://github.com/kubernetes/kubernetes/blob/15c3f1b11/staging/src/k8s.io/apiserver/pkg/server/httplog/httplog.go#L168)
```
package main
import (
"fmt"
"k8s.io/klog/v2"
"net/http"
"time"
)
type respLogger struct {
status int
statusStack string
addedInfo string
req *http.Request
}
func (rl *respLogger) Log(latency time.Duration) {
klog.InfoDepth(1, fmt.Sprintf("verb=%q URI=%q latency=%v resp=%v UserAgent=%q srcIP=%q: %v%v",
rl.req.Method, rl.req.RequestURI,
latency, rl.status,
rl.req.UserAgent(), rl.req.RemoteAddr,
rl.statusStack, rl.addedInfo,
))
}
func (rl *respLogger) LogArgs(latency time.Duration) []interface{} {
return []interface{}{
"verb", rl.req.Method,
"URI", rl.req.RequestURI,
"latency", latency,
"resp", rl.status,
"userAgent", rl.req.UserAgent(),
"srcIP", rl.req.RemoteAddr,
}
}
func main() {
klog.InitFlags(nil)
// Setup
rl := respLogger{
status: 200,
req: &http.Request{
Method: "GET",
Header: map[string][]string{"User-Agent": {"Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/41.0. 2272.118 Safari/537.36."}},
RemoteAddr: "127.0.0.1",
RequestURI: "/metrics",
},
}
latency := time.Second
// Before migration
rl.Log(latency)
// After migration
klog.InfoS("Received HTTP request", rl.LogArgs(latency)...)
}
```

Log output before migration
```
I0528 19:15:22.737538 47512 logtest.go:52] verb="GET" URI="/metrics" latency=1s resp=200 UserAgent="Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/41.0. 2272.118 Safari/537.36." srcIP="127.0.0.1":
```
After
```
I0528 19:15:22.737588 47512 logtest.go:55] "Received HTTP request" verb="GET" URI="/metrics" latency="1s" resp=200 userAgent="Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/41.0. 2272.118 Safari/537.36." srcIP="127.0.0.1"
```

0 comments on commit 5e71635

Please sign in to comment.