output.go

/*
Copyright 2021 The Kubernetes Authors.

Licensed under the Apache License, Version 2.0 (the "License");
you may not use this file except in compliance with the License.
You may obtain a copy of the License at

    http://www.apache.org/licenses/LICENSE-2.0

Unless required by applicable law or agreed to in writing, software
distributed under the License is distributed on an "AS IS" BASIS,
WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
See the License for the specific language governing permissions and
limitations under the License.
*/

// Package test contains a reusable unit test for logging output and behavior.
//
// Experimental
//
// Notice: This package is EXPERIMENTAL and may be changed or removed in a
// later release.
package test

import (
	"bytes"
	"encoding/json"
	"errors"
	"flag"
	"fmt"
	"io"
	"regexp"
	"runtime"
	"strconv"
	"strings"
	"testing"
	"time"

	"github.com/go-logr/logr"

	"k8s.io/klog/v2"
)

// InitKlog must be called once in an init function of a test package to
// configure klog for testing with Output.
//
// Experimental
//
// Notice: This function is EXPERIMENTAL and may be changed or removed in a
// later release.
func InitKlog() {
	// klog gets configured so that it writes to a single output file that
	// will be set during tests with SetOutput.
	klog.InitFlags(nil)
	flag.Set("v", "10")
	flag.Set("log_file", "/dev/null")
	flag.Set("logtostderr", "false")
	flag.Set("alsologtostderr", "false")
	flag.Set("stderrthreshold", "10")
}

// OutputConfig contains optional settings for Output.
//
// Experimental
//
// Notice: This type is EXPERIMENTAL and may be changed or removed in a
// later release.
type OutputConfig struct {
	// NewLogger is called to create a new logger. If nil, output via klog
	// is tested. Support for -vmodule is optional.
	NewLogger func(out io.Writer, v int, vmodule string) logr.Logger

	// AsBackend enables testing through klog and the logger set there with
	// SetLogger.
	AsBackend bool

	// ExpectedOutputMapping replaces the builtin expected output for test
	// cases with something else. If nil or a certain case is not present,
	// the original text is used.
	//
	// The expected output uses <LINE> as a placeholder for the line of the
	// log call. The source code is always the output.go file itself. When
	// testing a logger directly, <WITH-VALUES-LINE> is used for the first
	// WithValues call, <WITH-VALUES-LINE-2> for a second and
	// <WITH-VALUES-LINE-3> for a third.
	ExpectedOutputMapping map[string]string

	// SupportsVModule indicates that the logger supports the vmodule
	// parameter. Ignored when logging through klog.
	SupportsVModule bool
}

// Output covers various special cases of emitting log output.
// It can be used for arbitrary logr.Logger implementations.
//
// The expected output is what klog would print. When testing loggers
// that emit different output, a mapping from klog output to the
// corresponding logger output must be provided, otherwise the
// test will compare against the expected klog output.
//
// Loggers will be tested with direct calls to Info or
// as backend for klog.
//
// Experimental
//
// Notice: This function is EXPERIMENTAL and may be changed or removed in a
// later release. The test cases and thus the expected output also may
// change.
func Output(t *testing.T, config OutputConfig) {
	tests := map[string]struct {
		withHelper bool // use wrappers that get skipped during stack unwinding
		withNames  []string
		// For a first WithValues call: logger1 := logger.WithValues()
		withValues []interface{}
		// For another WithValues call: logger2 := logger1.WithValues()
		moreValues []interface{}
		// For another WithValues call on the same logger as before: logger3 := logger1.WithValues()
		evenMoreValues []interface{}
		v              int
		vmodule        string
		text           string
		values         []interface{}
		err            error
		expectedOutput string
	}{
		"log with values": {
			text:   "test",
			values: []interface{}{"akey", "avalue"},
			expectedOutput: `I output.go:<LINE>] "test" akey="avalue"
`,
		},
		"call depth": {
			text:       "helper",
			withHelper: true,
			values:     []interface{}{"akey", "avalue"},
			expectedOutput: `I output.go:<LINE>] "helper" akey="avalue"
`,
		},
		"verbosity enabled": {
			text: "you see me",
			v:    9,
			expectedOutput: `I output.go:<LINE>] "you see me"
`,
		},
		"verbosity disabled": {
			text: "you don't see me",
			v:    11,
		},
		"vmodule": {
			text:    "v=11: you see me because of -vmodule output=11",
			v:       11,
			vmodule: "output=11",
		},
		"other vmodule": {
			text:    "v=11: you still don't see me because of -vmodule output_helper=11",
			v:       11,
			vmodule: "output_helper=11",
		},
		"log with name and values": {
			withNames: []string{"me"},
			text:      "test",
			values:    []interface{}{"akey", "avalue"},
			expectedOutput: `I output.go:<LINE>] "me: test" akey="avalue"
`,
		},
		"log with multiple names and values": {
			withNames: []string{"hello", "world"},
			text:      "test",
			values:    []interface{}{"akey", "avalue"},
			expectedOutput: `I output.go:<LINE>] "hello/world: test" akey="avalue"
`,
		},
		"override single value": {
			withValues: []interface{}{"akey", "avalue"},
			text:       "test",
			values:     []interface{}{"akey", "avalue2"},
			expectedOutput: `I output.go:<LINE>] "test" akey="avalue2"
`,
		},
		"override WithValues": {
			withValues: []interface{}{"duration", time.Hour, "X", "y"},
			text:       "test",
			values:     []interface{}{"duration", time.Minute, "A", "b"},
			expectedOutput: `I output.go:<LINE>] "test" X="y" duration="1m0s" A="b"
`,
		},
		"odd WithValues": {
			withValues: []interface{}{"keyWithoutValue"},
			moreValues: []interface{}{"anotherKeyWithoutValue"},
			text:       "test",
			expectedOutput: `I output.go:<LINE>] "test" keyWithoutValue="(MISSING)"
I output.go:<LINE>] "test" keyWithoutValue="(MISSING)" anotherKeyWithoutValue="(MISSING)"
I output.go:<LINE>] "test" keyWithoutValue="(MISSING)"
`,
		},
		"multiple WithValues": {
			withValues:     []interface{}{"firstKey", 1},
			moreValues:     []interface{}{"secondKey", 2},
			evenMoreValues: []interface{}{"secondKey", 3},
			text:           "test",
			expectedOutput: `I output.go:<LINE>] "test" firstKey=1
I output.go:<LINE>] "test" firstKey=1 secondKey=2
I output.go:<LINE>] "test" firstKey=1
I output.go:<LINE>] "test" firstKey=1 secondKey=3
`,
		},
		"empty WithValues": {
			withValues: []interface{}{},
			text:       "test",
			expectedOutput: `I output.go:<LINE>] "test"
`,
		},
		// TODO: unify behavior of loggers.
		// klog doesn't deduplicate, klogr and textlogger do. We can ensure via static code analysis
		// that this doesn't occur, so we shouldn't pay the runtime overhead for deduplication here
		// and remove that from klogr and textlogger (https://github.com/kubernetes/klog/issues/286).
		// 		"print duplicate keys in arguments": {
		// 			text:   "test",
		// 			values: []interface{}{"akey", "avalue", "akey", "avalue2"},
		// 			expectedOutput: `I output.go:<LINE>] "test" akey="avalue" akey="avalue2"
		// `,
		// 		},
		"preserve order of key/value pairs": {
			withValues: []interface{}{"akey9", "avalue9", "akey8", "avalue8", "akey1", "avalue1"},
			text:       "test",
			values:     []interface{}{"akey5", "avalue5", "akey4", "avalue4"},
			expectedOutput: `I output.go:<LINE>] "test" akey9="avalue9" akey8="avalue8" akey1="avalue1" akey5="avalue5" akey4="avalue4"
`,
		},
		"handle odd-numbers of KVs": {
			text:   "test",
			values: []interface{}{"akey", "avalue", "akey2"},
			expectedOutput: `I output.go:<LINE>] "test" akey="avalue" akey2="(MISSING)"
`,
		},
		"html characters": {
			text:   "test",
			values: []interface{}{"akey", "<&>"},
			expectedOutput: `I output.go:<LINE>] "test" akey="<&>"
`,
		},
		"quotation": {
			text:   `"quoted"`,
			values: []interface{}{"key", `"quoted value"`},
			expectedOutput: `I output.go:<LINE>] "\"quoted\"" key="\"quoted value\""
`,
		},
		"handle odd-numbers of KVs in both log values and Info args": {
			withValues: []interface{}{"basekey1", "basevar1", "basekey2"},
			text:       "test",
			values:     []interface{}{"akey", "avalue", "akey2"},
			expectedOutput: `I output.go:<LINE>] "test" basekey1="basevar1" basekey2="(MISSING)" akey="avalue" akey2="(MISSING)"
`,
		},
		"KObj": {
			text:   "test",
			values: []interface{}{"pod", klog.KObj(&kmeta{Name: "pod-1", Namespace: "kube-system"})},
			expectedOutput: `I output.go:<LINE>] "test" pod="kube-system/pod-1"
`,
		},
		"KObjs": {
			text: "test",
			values: []interface{}{"pods",
				klog.KObjs([]interface{}{
					&kmeta{Name: "pod-1", Namespace: "kube-system"},
					&kmeta{Name: "pod-2", Namespace: "kube-system"},
				})},
			expectedOutput: `I output.go:<LINE>] "test" pods=[kube-system/pod-1 kube-system/pod-2]
`,
		},
		"regular error types as value": {
			text:   "test",
			values: []interface{}{"err", errors.New("whoops")},
			expectedOutput: `I output.go:<LINE>] "test" err="whoops"
`,
		},
		"ignore MarshalJSON": {
			text:   "test",
			values: []interface{}{"err", &customErrorJSON{"whoops"}},
			expectedOutput: `I output.go:<LINE>] "test" err="whoops"
`,
		},
		"regular error types when using logr.Error": {
			text: "test",
			err:  errors.New("whoops"),
			expectedOutput: `E output.go:<LINE>] "test" err="whoops"
`,
		},
	}
	for n, test := range tests {
		t.Run(n, func(t *testing.T) {
			printWithLogger := func(logger logr.Logger) {
				for _, name := range test.withNames {
					logger = logger.WithName(name)
				}
				// When we have multiple WithValues calls, we test
				// first with the initial set of additional values, then
				// the combination, then again the original logger.
				// It must not have been modified. This produces
				// three log entries.
				logger = logger.WithValues(test.withValues...)
				loggers := []logr.Logger{logger}
				if test.moreValues != nil {
					loggers = append(loggers, logger.WithValues(test.moreValues...), logger)
				}
				if test.evenMoreValues != nil {
					loggers = append(loggers, logger.WithValues(test.evenMoreValues...))
				}
				for _, logger := range loggers {
					if test.withHelper {
						loggerHelper(logger, test.text, test.values)
					} else if test.err != nil {
						logger.Error(test.err, test.text, test.values...)
					} else {
						logger.V(test.v).Info(test.text, test.values...)
					}
				}
			}
			_, _, printWithLoggerLine, _ := runtime.Caller(0)

			printWithKlog := func() {
				kv := []interface{}{}
				haveKeyInValues := func(key interface{}) bool {
					for i := 0; i < len(test.values); i += 2 {
						if key == test.values[i] {
							return true
						}
					}
					return false
				}
				appendKV := func(withValues []interface{}) {
					if len(withValues)%2 != 0 {
						withValues = append(withValues, "(MISSING)")
					}
					for i := 0; i < len(withValues); i += 2 {
						if !haveKeyInValues(withValues[i]) {
							kv = append(kv, withValues[i], withValues[i+1])
						}
					}
				}
				// Here we need to emulate the handling of WithValues above.
				appendKV(test.withValues)
				kvs := [][]interface{}{copySlice(kv)}
				if test.moreValues != nil {
					appendKV(test.moreValues)
					kvs = append(kvs, copySlice(kv), copySlice(kvs[0]))
				}
				if test.evenMoreValues != nil {
					kv = copySlice(kvs[0])
					appendKV(test.evenMoreValues)
					kvs = append(kvs, copySlice(kv))
				}
				for _, kv := range kvs {
					if len(test.values) > 0 {
						kv = append(kv, test.values...)
					}
					text := test.text
					if len(test.withNames) > 0 {
						text = strings.Join(test.withNames, "/") + ": " + text
					}
					if test.withHelper {
						klogHelper(text, kv)
					} else if test.err != nil {
						klog.ErrorS(test.err, text, kv...)
					} else {
						klog.V(klog.Level(test.v)).InfoS(text, kv...)
					}
				}
			}
			_, _, printWithKlogLine, _ := runtime.Caller(0)

			testOutput := func(t *testing.T, expectedLine int, print func(buffer *bytes.Buffer)) {
				var tmpWriteBuffer bytes.Buffer
				klog.SetOutput(&tmpWriteBuffer)
				print(&tmpWriteBuffer)
				klog.Flush()

				actual := tmpWriteBuffer.String()
				// Strip varying header.
				re := `(?m)^(.).... ..:..:......... ....... output.go`
				actual = regexp.MustCompile(re).ReplaceAllString(actual, `${1} output.go`)

				// Inject expected line. This matches the if checks above, which are
				// the same for both printWithKlog and printWithLogger.
				callLine := expectedLine
				if test.withHelper {
					callLine -= 8
				} else if test.err != nil {
					callLine -= 6
				} else {
					callLine -= 4
				}
				expected := test.expectedOutput
				if repl, ok := config.ExpectedOutputMapping[expected]; ok {
					expected = repl
				}
				expected = strings.ReplaceAll(expected, "<LINE>", fmt.Sprintf("%d", callLine))
				expected = strings.ReplaceAll(expected, "<WITH-VALUES>", fmt.Sprintf("%d", expectedLine-18))
				expected = strings.ReplaceAll(expected, "<WITH-VALUES-2>", fmt.Sprintf("%d", expectedLine-15))
				expected = strings.ReplaceAll(expected, "<WITH-VALUES-3>", fmt.Sprintf("%d", expectedLine-12))
				if actual != expected {
					t.Errorf("Output mismatch. Expected:\n%s\nActual:\n%s\n", expected, actual)
				}
			}

			if config.NewLogger == nil {
				// Test klog.
				testOutput(t, printWithKlogLine, func(buffer *bytes.Buffer) {
					printWithKlog()
				})
				return
			}

			if config.AsBackend {
				testOutput(t, printWithKlogLine, func(buffer *bytes.Buffer) {
					klog.SetLogger(config.NewLogger(buffer, 10, ""))
					defer klog.ClearLogger()
					printWithKlog()
				})
				return
			}

			if test.vmodule != "" && !config.SupportsVModule {
				t.Skip("vmodule not supported")
			}

			testOutput(t, printWithLoggerLine, func(buffer *bytes.Buffer) {
				printWithLogger(config.NewLogger(buffer, 10, test.vmodule))
			})
		})
	}

	if config.NewLogger == nil || config.AsBackend {
		// Test all klog output functions.
		//
		// Each test case must be defined with the same number of
		// lines, then the source code location of the call itself
		// can be computed below.
		tests := []struct {
			name    string
			logFunc func()
			output  string
		}{
			{
				name:    "Info",
				logFunc: func() { klog.Info("hello", "world") },
				output:  "I output.go:<LINE>] helloworld\n", // This looks odd, but simply is how klog works.
			},
			{
				name:    "InfoDepth",
				logFunc: func() { klog.InfoDepth(0, "hello", "world") },
				output:  "I output.go:<LINE>] helloworld\n",
			},
			{
				name:    "Infoln",
				logFunc: func() { klog.Infoln("hello", "world") },
				output:  "I output.go:<LINE>] hello world\n",
			},
			{
				name:    "InfolnDepth",
				logFunc: func() { klog.InfolnDepth(0, "hello", "world") },
				output:  "I output.go:<LINE>] hello world\n",
			},
			{
				name:    "Infof",
				logFunc: func() { klog.Infof("hello %s", "world") },
				output:  "I output.go:<LINE>] hello world\n",
			},
			{
				name:    "InfofDepth",
				logFunc: func() { klog.InfofDepth(0, "hello %s", "world") },
				output:  "I output.go:<LINE>] hello world\n",
			},
			{
				name:    "InfoS",
				logFunc: func() { klog.InfoS("hello", "what", "world") },
				output:  "I output.go:<LINE>] \"hello\" what=\"world\"\n",
			},
			{
				name:    "InfoSDepth",
				logFunc: func() { klog.InfoSDepth(0, "hello", "what", "world") },
				output:  "I output.go:<LINE>] \"hello\" what=\"world\"\n",
			},
			{
				name:    "Warning",
				logFunc: func() { klog.Warning("hello", "world") },
				output:  "W output.go:<LINE>] helloworld\n",
			},
			{
				name:    "WarningDepth",
				logFunc: func() { klog.WarningDepth(0, "hello", "world") },
				output:  "W output.go:<LINE>] helloworld\n",
			},
			{
				name:    "Warningln",
				logFunc: func() { klog.Warningln("hello", "world") },
				output:  "W output.go:<LINE>] hello world\n",
			},
			{
				name:    "WarninglnDepth",
				logFunc: func() { klog.WarninglnDepth(0, "hello", "world") },
				output:  "W output.go:<LINE>] helloworld\n", // BUG
			},
			{
				name:    "Warningf",
				logFunc: func() { klog.Warningf("hello %s", "world") },
				output:  "W output.go:<LINE>] hello world\n",
			},
			{
				name:    "WarningfDepth",
				logFunc: func() { klog.WarningfDepth(0, "hello %s", "world") },
				output:  "W output.go:<LINE>] hello world\n",
			},
			{
				name:    "Error",
				logFunc: func() { klog.Error("hello", "world") },
				output:  "E output.go:<LINE>] helloworld\n",
			},
			{
				name:    "ErrorDepth",
				logFunc: func() { klog.ErrorDepth(0, "hello", "world") },
				output:  "E output.go:<LINE>] helloworld\n",
			},
			{
				name:    "Errorln",
				logFunc: func() { klog.Errorln("hello", "world") },
				output:  "E output.go:<LINE>] hello world\n",
			},
			{
				name:    "ErrorlnDepth",
				logFunc: func() { klog.ErrorlnDepth(0, "hello", "world") },
				output:  "E output.go:<LINE>] helloworld\n", // BUG
			},
			{
				name:    "Errorf",
				logFunc: func() { klog.Errorf("hello %s", "world") },
				output:  "E output.go:<LINE>] hello world\n",
			},
			{
				name:    "ErrorfDepth",
				logFunc: func() { klog.ErrorfDepth(0, "hello %s", "world") },
				output:  "E output.go:<LINE>] hello world\n",
			},
			{
				name:    "ErrorS",
				logFunc: func() { klog.ErrorS(errors.New("hello"), "world") },
				output:  "E output.go:<LINE>] \"world\" err=\"hello\"\n",
			},
			{
				name:    "ErrorSDepth",
				logFunc: func() { klog.ErrorSDepth(0, errors.New("hello"), "world") },
				output:  "E output.go:<LINE>] \"world\" err=\"hello\"\n",
			},
			{
				name:    "V().Info",
				logFunc: func() { klog.V(1).Info("hello", "one", "world") },
				output:  "I output.go:<LINE>] hellooneworld\n",
			},
			{
				name:    "V().InfoDepth",
				logFunc: func() { klog.V(1).InfoDepth(0, "hello", "one", "world") },
				output:  "I output.go:<LINE>] hellooneworld\n",
			},
			{
				name:    "V().Infoln",
				logFunc: func() { klog.V(1).Infoln("hello", "one", "world") },
				output:  "I output.go:<LINE>] hello one world\n",
			},
			{
				name:    "V().InfolnDepth",
				logFunc: func() { klog.V(1).InfolnDepth(0, "hello", "one", "world") },
				output:  "I output.go:<LINE>] hello one world\n",
			},
			{
				name:    "V().Infof",
				logFunc: func() { klog.V(1).Infof("hello %s %s", "one", "world") },
				output:  "I output.go:<LINE>] hello one world\n",
			},
			{
				name:    "V().InfofDepth",
				logFunc: func() { klog.V(1).InfofDepth(0, "hello %s %s", "one", "world") },
				output:  "I output.go:<LINE>] hello one world\n",
			},
			{
				name:    "V().InfoS",
				logFunc: func() { klog.V(1).InfoS("hello", "what", "one world") },
				output:  "I output.go:<LINE>] \"hello\" what=\"one world\"\n",
			},
			{
				name:    "V().InfoSDepth",
				logFunc: func() { klog.V(1).InfoSDepth(0, "hello", "what", "one world") },
				output:  "I output.go:<LINE>] \"hello\" what=\"one world\"\n",
			},
			{
				name:    "V().ErrorS",
				logFunc: func() { klog.V(1).ErrorS(errors.New("hello"), "one world") },
				output:  "E output.go:<LINE>] \"one world\" err=\"hello\"\n",
			},
		}
		_, _, line, _ := runtime.Caller(0)

		for i, test := range tests {
			t.Run(test.name, func(t *testing.T) {
				var buffer bytes.Buffer
				if config.NewLogger == nil {
					klog.SetOutput(&buffer)
				} else {
					klog.SetLogger(config.NewLogger(&buffer, 10, ""))
					defer klog.ClearLogger()
				}
				test.logFunc()
				klog.Flush()

				actual := buffer.String()
				// Strip varying header.
				re := `(?m)^(.).... ..:..:......... ....... output.go`
				actual = regexp.MustCompile(re).ReplaceAllString(actual, `${1} output.go`)

				// Inject expected line. This matches the if checks above, which are
				// the same for both printWithKlog and printWithLogger.
				callLine := line + 1 - (len(tests)-i)*5
				expected := test.output

				// When klog does string formating for
				// non-structured calls, it passes the entire
				// result, including a trailing newline, to
				// Logger.Info.
				if config.NewLogger != nil &&
					!strings.HasSuffix(test.name, "S") &&
					!strings.HasSuffix(test.name, "SDepth") {
					// klog: I output.go:<LINE>] hello world
					// with logger: I output.go:<LINE>] "hello world\n"
					index := strings.Index(expected, "] ")
					if index == -1 {
						t.Fatalf("did not find ] separator: %s", expected)
					}
					expected = expected[0:index+2] + strconv.Quote(expected[index+2:]) + "\n"

					// Warnings become info messages.
					if strings.HasPrefix(expected, "W") {
						expected = "I" + expected[1:]
					}
				}

				if repl, ok := config.ExpectedOutputMapping[expected]; ok {
					expected = repl
				}
				expected = strings.ReplaceAll(expected, "<LINE>", fmt.Sprintf("%d", callLine))
				if actual != expected {
					t.Errorf("Output mismatch. Expected:\n%s\nActual:\n%s\n", expected, actual)
				}
			})
		}
	}
}

func copySlice(in []interface{}) []interface{} {
	return append([]interface{}{}, in...)
}

type kmeta struct {
	Name, Namespace string
}

func (k kmeta) GetName() string {
	return k.Name
}

func (k kmeta) GetNamespace() string {
	return k.Namespace
}

var _ klog.KMetadata = kmeta{}

type customErrorJSON struct {
	s string
}

var _ error = &customErrorJSON{}
var _ json.Marshaler = &customErrorJSON{}

func (e *customErrorJSON) Error() string {
	return e.s
}

func (e *customErrorJSON) MarshalJSON() ([]byte, error) {
	return json.Marshal(strings.ToUpper(e.s))
}