testinglogger_test.go

/*
Copyright 2019 The Kubernetes Authors.
Copyright 2020 Intel Coporation.

SPDX-License-Identifier: Apache-2.0
*/

package ktesting_test

import (
	"bytes"
	"errors"
	"flag"
	"fmt"
	"regexp"
	"runtime"
	"sync"
	"testing"

	"k8s.io/klog/v2"
	"k8s.io/klog/v2/ktesting"
)

func TestInfo(t *testing.T) {
	tests := map[string]struct {
		text           string
		withValues     []interface{}
		keysAndValues  []interface{}
		names          []string
		err            error
		expectedOutput string
	}{
		"should log with values passed to keysAndValues": {
			text:          "test",
			keysAndValues: []interface{}{"akey", "avalue"},
			expectedOutput: `INFO test akey="avalue"
`,
		},
		"should support single name": {
			names:         []string{"hello"},
			text:          "test",
			keysAndValues: []interface{}{"akey", "avalue"},
			expectedOutput: `INFO hello: test akey="avalue"
`,
		},
		"should support multiple names": {
			names:         []string{"hello", "world"},
			text:          "test",
			keysAndValues: []interface{}{"akey", "avalue"},
			expectedOutput: `INFO hello/world: test akey="avalue"
`,
		},
		"should not print duplicate keys with the same value": {
			text:          "test",
			keysAndValues: []interface{}{"akey", "avalue", "akey", "avalue"},
			expectedOutput: `INFO test akey="avalue" akey="avalue"
`,
		},
		"should only print the last duplicate key when the values are passed to Info": {
			text:          "test",
			keysAndValues: []interface{}{"akey", "avalue", "akey", "avalue2"},
			expectedOutput: `INFO test akey="avalue" akey="avalue2"
`,
		},
		"should only print the duplicate key that is passed to Info if one was passed to the logger": {
			withValues:    []interface{}{"akey", "avalue"},
			text:          "test",
			keysAndValues: []interface{}{"akey", "avalue"},
			expectedOutput: `INFO test akey="avalue"
`,
		},
		"should only print the key passed to Info when one is already set on the logger": {
			withValues:    []interface{}{"akey", "avalue"},
			text:          "test",
			keysAndValues: []interface{}{"akey", "avalue2"},
			expectedOutput: `INFO test akey="avalue2"
`,
		},
		"should correctly handle odd-numbers of KVs": {
			text:          "test",
			keysAndValues: []interface{}{"akey", "avalue", "akey2"},
			expectedOutput: `INFO test akey="avalue" akey2="(MISSING)"
`,
		},
		"should correctly html characters": {
			text:          "test",
			keysAndValues: []interface{}{"akey", "<&>"},
			expectedOutput: `INFO test akey="<&>"
`,
		},
		"should correctly handle odd-numbers of KVs in both log values and Info args": {
			withValues:    []interface{}{"basekey1", "basevar1", "basekey2"},
			text:          "test",
			keysAndValues: []interface{}{"akey", "avalue", "akey2"},
			expectedOutput: `INFO test basekey1="basevar1" basekey2="(MISSING)" akey="avalue" akey2="(MISSING)"
`,
		},
		"should correctly print regular error types": {
			text:          "test",
			keysAndValues: []interface{}{"err", errors.New("whoops")},
			expectedOutput: `INFO test err="whoops"
`,
		},
		"should correctly print regular error types when using logr.Error": {
			text: "test",
			err:  errors.New("whoops"),
			expectedOutput: `ERROR test err="whoops"
`,
		},
	}
	for n, test := range tests {
		t.Run(n, func(t *testing.T) {
			var buffer logToBuf
			klogr := ktesting.NewLogger(&buffer, ktesting.NewConfig())
			for _, name := range test.names {
				klogr = klogr.WithName(name)
			}
			klogr = klogr.WithValues(test.withValues...)

			if test.err != nil {
				klogr.Error(test.err, test.text, test.keysAndValues...)
			} else {
				klogr.Info(test.text, test.keysAndValues...)
			}

			actual := buffer.String()
			if actual != test.expectedOutput {
				t.Errorf("Expected:\n%sActual:\n%s\n", test.expectedOutput, actual)
			}
		})
	}
}

func TestCallDepth(t *testing.T) {
	logger := ktesting.NewLogger(t, ktesting.NewConfig())
	logger.Info("hello world")
}

type logToBuf struct {
	ktesting.NopTL
	bytes.Buffer
}

func (l *logToBuf) Helper() {
}

func (l *logToBuf) Log(args ...interface{}) {
	for i, arg := range args {
		if i > 0 {
			l.Write([]byte(" "))
		}
		l.Write([]byte(fmt.Sprintf("%s", arg)))
	}
	l.Write([]byte("\n"))
}

func TestStop(t *testing.T) {
	// This test is set up so that a subtest spawns a goroutine and that
	// goroutine logs through ktesting *after* the subtest has
	// completed. This is not supported by testing.T.Log and normally
	// leads to:
	//   panic: Log in goroutine after TestGoroutines/Sub has completed: INFO hello world
	//
	// It works with ktesting if (and only if) logging gets redirected to klog
	// before returning from the test.

	// Capture output for testing.
	state := klog.CaptureState()
	defer state.Restore()
	var output bytes.Buffer
	var fs flag.FlagSet
	klog.InitFlags(&fs)
	fs.Set("alsologtostderr", "false")
	fs.Set("logtostderr", "false")
	fs.Set("one_output", "true")
	klog.SetOutput(&output)

	var line int
	var wg1, wg2 sync.WaitGroup
	wg1.Add(1)
	wg2.Add(1)
	t.Run("Sub", func(t *testing.T) {
		logger, _ := ktesting.NewTestContext(t)
		go func() {
			defer wg2.Done()

			// Wait for test to have returned.
			wg1.Wait()

			// This output must go to klog because the test has
			// completed.
			_, _, line, _ = runtime.Caller(0)
			logger.Info("simple info message")
			logger.Error(nil, "error message")
			logger.WithName("me").WithValues("completed", true).Info("complex info message", "anotherValue", 1)
		}()
	})
	// Allow goroutine above to proceed.
	wg1.Done()

	// Ensure that goroutine has completed.
	wg2.Wait()

	actual := output.String()
	actual = regexp.MustCompile(`(?m)^.* testinglogger_test.go:`).ReplaceAllString(actual, `testinglogger_test.go:`)
	expected := fmt.Sprintf(`testinglogger_test.go:%d] "TestStop/Sub leaked goroutine: simple info message"
testinglogger_test.go:%d] "TestStop/Sub leaked goroutine: error message"
testinglogger_test.go:%d] "TestStop/Sub leaked goroutine/me: complex info message" completed=true anotherValue=1
`,
		line+1, line+2, line+3)
	if actual != expected {
		t.Errorf("Output does not match. Expected:\n%s\nActual:\n%s\n", expected, actual)
	}
}