Merge pull request #6283 from serathius/logging-guidelines

Update logging guidelines

2 files changed, 92 insertions, 41 deletions

diff --git a/contributors/devel/sig-instrumentation/logging.md b/contributors/devel/sig-instrumentation/logging.md
index 16b6a044..11911c1a 100644
--- a/contributors/devel/sig-instrumentation/logging.md
+++ b/contributors/devel/sig-instrumentation/logging.md
@@ -1,37 +1,77 @@
-## Logging Conventions
+## Logging
 
-The following conventions for the klog levels to use.
-[klog](http://godoc.org/github.com/kubernetes/klog) is globally preferred to
-[log](http://golang.org/pkg/log/) for better runtime control.
+This document provides an overview of  the recommended way to develop and implement
+logging for components of Kubernetes.
+For [k/kubernetes](https://github.com/kubernetes/kubernetes) these conventions should be seen
+as a strong recommendation, however any Kubernetes or external project is welcome to follow
+the guidelines below. Most of the ideas can be applied more broadly.
 
-Shared libraries, such as `client-go`, should not use `klog.ErrorS()` and `klog.InfoS()`,
+### Logging in Kubernetes
+
+Kubernetes project uses [klog](https://github.com/kubernetes/klog) for logging.
+This library was created as a permanent fork of glog, as the original project was no longer developed. 
+With the introduction of [Structured Logging](https://github.com/kubernetes/enhancements/tree/master/keps/sig-instrumentation/1602-structured-logging) and [Contextual Logging](https://github.com/kubernetes/enhancements/blob/master/keps/sig-instrumentation/3077-contextual-logging/README.md), Kubernetes is being migrated to use [logr](https://github.com/go-logr/logr) as its logging interface. Any changes in klog are done to ensure a smooth transition to `logr`. Klog is then only used to manage the logging configuration (`SetLogger`, retrieving the logger) and its logging calls should not be used anymore.
+``
+
+For projects that want to integrate with Kubernetes or write the same log format, retrieving a `logr.Logger` instance from klog will return an implementation that emits log output the same way as the traditional klog logging calls.
+
+### Logging Conventions
+
+### When not to log?
+
+Shared libraries, such as [`client-go`](https://github.com/kubernetes/client-go), should _not_
+log errors themselves
 but just return `error`, because client libraries may be used in CLI UIs that wish to control output.
 
-Please see the [Structured Logging Guide](migration-to-structured-logging.md#structured-logging-in-kubernetes) for more information on how to set keys and values in structured logs.
+### How to log
 
-* klog.ErrorS() - Errors should be used to indicate unexpected behaviours in code, like unexpected errors returned by subroutine function calls.
-Logs generated by `ErrorS` command may be enhanced with additional debug information (by logging library). Calling `ErrorS` with `nil` as error may be acceptable if there is error condition that deserves a stack trace at this origin point.
+There are two main klog methods for writing logs: `klog.InfoS` and `klog.ErrorS`. Both methods are part of a [logr](https://github.com/go-logr/logr) compatible interface.
+For those two functions exists additional flavors, like `klog.V(2).InfoS` that allows caller to increase log verbosity (making it only available when `--v=2` flag is provided to binary) and `klog.InfoSDepth` with `klog.ErorSDepth` that give control to change caller information.
+
+Any other non-structured (without `S`) klog methods like `klog.Infof` that use old C like string format interface are no longer recommended for use. 
+Those log calls using those methods should be migrated to their structured variants.
+Please see the [Structured Logging Guide](migration-to-structured-logging.md#structured-logging-in-kubernetes) for more information on how to migrate such logs.
+
+All structured logging methods accept the log message as a string, along with any number of key/value pairs that you provide via a variadic `interface{}` argument.
+As variadic arguments represent key value pairs, they should always be even in count with first element being key of type string and second value of any type matching that key.
 
-* klog.InfoS() -  Structured logs to the INFO log. `InfoS` should be used for routine logging. It can also be used to log warnings for expected errors (errors that can happen during routine operations).
+Prototype:
+```go
+func InfoS(message string, keysAndValues ...interface{})
+func InfoSDepth(depth int, message string, keysAndValues ...interface{})
+func ErrorS(err error, message string, keysAndValues ...interface{})
+func ErrorSDepth(depth int, err error, message string, keysAndValues ...interface{})
+```
+
+Example:
+```go
+klog.InfoS("Received HTTP request", "method", "GET", "URL", "/metrics", "latency", time.Second)
+```
+
+### What method to use?
+
+* `klog.ErrorS` - Errors should be used to indicate unexpected behaviours in code, like unexpected errors returned by subroutine function calls.
+Logs generated by `ErrorS` command may be enhanced with additional debug information (by logging library). Calling `ErrorS` with `nil` as error may be acceptable if there is error condition that deserves a stack trace at this origin point.
 
-* klog.InfoS() has multiple levels:
-  * klog.V(0) - Generally useful for this to ALWAYS be visible to an operator
+* `klog.InfoS` -  Structured logs to the INFO log. `InfoS` should be used for routine logging. It can also be used to log warnings for expected errors (errors that can happen during routine operations).
+  Depending on log severity it's important to pick a proper verbosity level to ensure that consumer is neither under nor overwhelmed by log volume:
+  * `klog.V(0).InfoS` = `klog.InfoS` - Generally useful for this to **always** be visible to a cluster operator
     * Programmer errors
     * Logging extra info about a panic
     * CLI argument handling
-  * klog.V(1) - A reasonable default log level if you don't want verbosity.
+  * `klog.V(1).InfoS` - A reasonable default log level if you don't want verbosity.
     * Information about config (listening on X, watching Y)
     * Errors that repeat frequently that relate to conditions that can be corrected (pod detected as unhealthy)
-  * klog.V(2) - Useful steady state information about the service and important log messages that may correlate to significant changes in the system.  This is the recommended default log level for most systems.
+  * `klog.V(2).InfoS` - Useful steady state information about the service and important log messages that may correlate to significant changes in the system.  This is the recommended default log level for most systems.
     * Logging HTTP requests and their exit code
     * System state changing (killing pod)
     * Controller state change events (starting pods)
     * Scheduler log messages
-  * klog.V(3) - Extended information about changes
+  * `klog.V(3).InfoS` - Extended information about changes
     * More info about system state changes
-  * klog.V(4) - Debug level verbosity
+  * `klog.V(4).InfoS` - Debug level verbosity
     * Logging in particularly thorny parts of code where you may want to come back later and check it
-  * klog.V(5) - Trace level verbosity
+  * `klog.V(5).InfoS` - Trace level verbosity
     * Context to understand the steps leading up to errors and warnings
     * More information for troubleshooting reported issues
 
diff --git a/contributors/devel/sig-instrumentation/migration-to-structured-logging.md b/contributors/devel/sig-instrumentation/migration-to-structured-logging.md
index b6c0a18d..cbe5c6d7 100644
--- a/contributors/devel/sig-instrumentation/migration-to-structured-logging.md
+++ b/contributors/devel/sig-instrumentation/migration-to-structured-logging.md
@@ -19,7 +19,7 @@ With organized, milestone-based, large-scale migration we try to target delivera
 
 For non-organized migrations, the onus is, generally, on the individual contributors.
 
-* Organized Migration
+#### Organized Migration
 
 Organized migration is carried out in a two state cycle aligning with the cadence of Kubernetes releases. 
 
@@ -27,7 +27,7 @@ In the first stage, we pick a particular migration milestone & create an issue t
 
 In the second milestone, we take a break from migration to analyze results & improve our existing processes. Adding structured information to logs is a very costly & time-consuming affair. Setting aside time in the second stage to collect feedback, analyze the impact of changes on the log volume & performance, and better our PR review process helps us avoid mistakes and duplicate efforts.
 
-* Non-organized migration
+#### Non-organized migration
 
 As aforementioned, our non-organized migration efforts are spearheaded by individual contributors who need to migrate particular code sections to utilize new features early. 
 
@@ -40,7 +40,8 @@ Before sending a PR our way, please ensure that there isn't one already in place
 ### Current status
 
 * 1.21 Kubelet was migrated
-* 1.22 We are collecting feedback and making improvements to the migration process.
+* 1.22 Collected feedback and improved the process.
+* 1.23 kube-scheduler and kube-proxy were migrated.
 
 ## Sending a Structured Logging Migration Pull Request
 
@@ -172,7 +173,7 @@ type KMetadata interface {
 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 objects references
+1. Ensure that value is properly passed
 1. Verify log output
 
 ## Change log functions to structured equivalent
@@ -378,32 +379,35 @@ func ChangePodStatus(newStatus, currentStatus string) {
 [lowerCamelCase]: https://en.wiktionary.org/wiki/lowerCamelCase
 [alphanumeric]: https://en.wikipedia.org/wiki/Alphanumeric
 
-### Use `klog.KObj` and `klog.KRef` for Kubernetes objects
+## Good practice for passing values in structured logging
 
-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.
+When passing a value for a key-value pair, please use following rules:
+* Prefer using Kubernetes objects (for example `*v1.Pod`) and log them using `klog.KObj`
+  * When the original object is not available, use `klog.KRef` instead
+* Pass structured values directly (avoid calling `.String()` on them first)
+* When the goal is to log a `[]byte` array as string, explicitly convert with `string(<byte array>)`.
+
+### Prefer using Kubernetes objects (for example `*v1.Pod`) and log them using `klog.KObj`
+
+As part of the structured logging migration, we want to ensure that Kubernetes object references are
+consistent within the
+codebase. Two new utility functions were introduced to klog: `klog.KObj` and `klog.KRef`.
+
+Any existing logging code that makes a reference (such as name, namespace) to a Kubernetes
+object (for example: Pod, Node, Deployment, CustomResourceDefinition) should be rewritten to
+utilize the new functions.
+
+Logging using this method will ensure that log output include a proper and correctly formatted reference
+to that object. The formatting / serialization is automatically selected depending on the output log format.
+For example, the same object could be represented as `<namespace>/<name>` in
+plain text and as `{"namespace": "<namespace>", "name": "<name>"}` in JSON.
+In situations when object `UID` is would be beneficial for log, it should be added as separate key 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)
+   klog.Infof("Updated pod(%s) with name %s in namespace %s", pod.Uid, pod.Name, pod.Namespace)
 }
 ```
 should be changed to
@@ -414,6 +418,7 @@ func updatePod(pod *covev1.Pod) {
 }
 ```
 
+### When the original object is not available, use `klog.KRef` instead
 `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.
@@ -434,7 +439,13 @@ func updateNode(nodeName string) {
 }
 ```
 
-### Verify log output
+### Pass structured values directly
+
+By passing whole structure without any marshalling we can allow logging library to make the decision for us.
+This is especially beneficial when Kubernetes supports different log format, so the logging library can make decision based on that.
+For example using `<namespace>/<name>` when writing in text format and `{"namespace": "<namespace>", "name": "<name>"}` for json format.
+
+## 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