testinglogger_test.go

Documentation: k8s.io/klog/v2/ktesting

     1  /*
     2  Copyright 2019 The Kubernetes Authors.
     3  Copyright 2020 Intel Corporation.
     4  
     5  SPDX-License-Identifier: Apache-2.0
     6  */
     7  
     8  package ktesting_test
     9  
    10  import (
    11  	"bytes"
    12  	"errors"
    13  	"flag"
    14  	"fmt"
    15  	"regexp"
    16  	"runtime"
    17  	"sync"
    18  	"testing"
    19  	"time"
    20  
    21  	"k8s.io/klog/v2"
    22  	"k8s.io/klog/v2/internal/test/require"
    23  	"k8s.io/klog/v2/ktesting"
    24  )
    25  
    26  var headerRe = regexp.MustCompile(`([IE])[[:digit:]]{4} [[:digit:]]{2}:[[:digit:]]{2}:[[:digit:]]{2}\.[[:digit:]]{6}\] `)
    27  
    28  func TestInfo(t *testing.T) {
    29  	tests := map[string]struct {
    30  		text           string
    31  		withValues     []interface{}
    32  		keysAndValues  []interface{}
    33  		names          []string
    34  		err            error
    35  		expectedOutput string
    36  	}{
    37  		"should log with values passed to keysAndValues": {
    38  			text:          "test",
    39  			keysAndValues: []interface{}{"akey", "avalue"},
    40  			expectedOutput: `Ixxx test akey="avalue"
    41  `,
    42  		},
    43  		"should support single name": {
    44  			names:         []string{"hello"},
    45  			text:          "test",
    46  			keysAndValues: []interface{}{"akey", "avalue"},
    47  			expectedOutput: `Ixxx hello: test akey="avalue"
    48  `,
    49  		},
    50  		"should support multiple names": {
    51  			names:         []string{"hello", "world"},
    52  			text:          "test",
    53  			keysAndValues: []interface{}{"akey", "avalue"},
    54  			expectedOutput: `Ixxx hello/world: test akey="avalue"
    55  `,
    56  		},
    57  		"should not print duplicate keys with the same value": {
    58  			text:          "test",
    59  			keysAndValues: []interface{}{"akey", "avalue", "akey", "avalue"},
    60  			expectedOutput: `Ixxx test akey="avalue" akey="avalue"
    61  `,
    62  		},
    63  		"should only print the last duplicate key when the values are passed to Info": {
    64  			text:          "test",
    65  			keysAndValues: []interface{}{"akey", "avalue", "akey", "avalue2"},
    66  			expectedOutput: `Ixxx test akey="avalue" akey="avalue2"
    67  `,
    68  		},
    69  		"should only print the duplicate key that is passed to Info if one was passed to the logger": {
    70  			withValues:    []interface{}{"akey", "avalue"},
    71  			text:          "test",
    72  			keysAndValues: []interface{}{"akey", "avalue"},
    73  			expectedOutput: `Ixxx test akey="avalue"
    74  `,
    75  		},
    76  		"should only print the key passed to Info when one is already set on the logger": {
    77  			withValues:    []interface{}{"akey", "avalue"},
    78  			text:          "test",
    79  			keysAndValues: []interface{}{"akey", "avalue2"},
    80  			expectedOutput: `Ixxx test akey="avalue2"
    81  `,
    82  		},
    83  		"should correctly handle odd-numbers of KVs": {
    84  			text:          "test",
    85  			keysAndValues: []interface{}{"akey", "avalue", "akey2"},
    86  			expectedOutput: `Ixxx test akey="avalue" akey2="(MISSING)"
    87  `,
    88  		},
    89  		"should correctly html characters": {
    90  			text:          "test",
    91  			keysAndValues: []interface{}{"akey", "<&>"},
    92  			expectedOutput: `Ixxx test akey="<&>"
    93  `,
    94  		},
    95  		"should correctly handle odd-numbers of KVs in both log values and Info args": {
    96  			withValues:    []interface{}{"basekey1", "basevar1", "basekey2"},
    97  			text:          "test",
    98  			keysAndValues: []interface{}{"akey", "avalue", "akey2"},
    99  			expectedOutput: `Ixxx test basekey1="basevar1" basekey2="(MISSING)" akey="avalue" akey2="(MISSING)"
   100  `,
   101  		},
   102  		"should correctly print regular error types": {
   103  			text:          "test",
   104  			keysAndValues: []interface{}{"err", errors.New("whoops")},
   105  			expectedOutput: `Ixxx test err="whoops"
   106  `,
   107  		},
   108  		"should correctly print regular error types when using logr.Error": {
   109  			text: "test",
   110  			err:  errors.New("whoops"),
   111  			expectedOutput: `Exxx test err="whoops"
   112  `,
   113  		},
   114  	}
   115  	for n, test := range tests {
   116  		t.Run(n, func(t *testing.T) {
   117  			var buffer logToBuf
   118  			klogr := ktesting.NewLogger(&buffer, ktesting.NewConfig())
   119  			for _, name := range test.names {
   120  				klogr = klogr.WithName(name)
   121  			}
   122  			klogr = klogr.WithValues(test.withValues...)
   123  
   124  			if test.err != nil {
   125  				klogr.Error(test.err, test.text, test.keysAndValues...)
   126  			} else {
   127  				klogr.Info(test.text, test.keysAndValues...)
   128  			}
   129  
   130  			actual := buffer.String()
   131  			actual = headerRe.ReplaceAllString(actual, `${1}xxx `)
   132  			if actual != test.expectedOutput {
   133  				t.Errorf("Expected:\n%sActual:\n%s\n", test.expectedOutput, actual)
   134  			}
   135  		})
   136  	}
   137  }
   138  
   139  func TestCallDepth(t *testing.T) {
   140  	logger := ktesting.NewLogger(t, ktesting.NewConfig())
   141  	logger.Info("hello world")
   142  }
   143  
   144  type logToBuf struct {
   145  	ktesting.NopTL
   146  	bytes.Buffer
   147  }
   148  
   149  func (l *logToBuf) Helper() {
   150  }
   151  
   152  func (l *logToBuf) Log(args ...interface{}) {
   153  	for i, arg := range args {
   154  		if i > 0 {
   155  			l.Write([]byte(" "))
   156  		}
   157  		l.Write([]byte(fmt.Sprintf("%s", arg)))
   158  	}
   159  	l.Write([]byte("\n"))
   160  }
   161  
   162  func TestStop(t *testing.T) {
   163  	// This test is set up so that a subtest spawns a goroutine and that
   164  	// goroutine logs through ktesting *after* the subtest has
   165  	// completed. This is not supported by testing.T.Log and normally
   166  	// leads to:
   167  	//   panic: Log in goroutine after TestGoroutines/Sub has completed: INFO hello world
   168  	//
   169  	// It works with ktesting if (and only if) logging gets redirected to klog
   170  	// before returning from the test.
   171  
   172  	// Capture output for testing.
   173  	state := klog.CaptureState()
   174  	defer state.Restore()
   175  	var output bytes.Buffer
   176  	var fs flag.FlagSet
   177  	klog.InitFlags(&fs)
   178  	require.NoError(t, fs.Set("alsologtostderr", "false"))
   179  	require.NoError(t, fs.Set("logtostderr", "false"))
   180  	require.NoError(t, fs.Set("stderrthreshold", "FATAL"))
   181  	require.NoError(t, fs.Set("one_output", "true"))
   182  	klog.SetOutput(&output)
   183  
   184  	var logger klog.Logger
   185  	var line int
   186  	var wg1, wg2 sync.WaitGroup
   187  	wg1.Add(1)
   188  	wg2.Add(1)
   189  	t.Run("Sub", func(t *testing.T) {
   190  		logger, _ = ktesting.NewTestContext(t)
   191  		go func() {
   192  			defer wg2.Done()
   193  
   194  			// Wait for test to have returned.
   195  			wg1.Wait()
   196  
   197  			// This output must go to klog because the test has
   198  			// completed.
   199  			_, _, line, _ = runtime.Caller(0)
   200  			logger.Info("simple info message")
   201  			logger.Error(nil, "error message")
   202  			time.Sleep(15 * time.Second)
   203  			logger.WithName("me").WithValues("completed", true).Info("complex info message", "anotherValue", 1)
   204  		}()
   205  	})
   206  	// Allow goroutine above to proceed.
   207  	wg1.Done()
   208  
   209  	// Ensure that goroutine has completed.
   210  	wg2.Wait()
   211  
   212  	actual := output.String()
   213  
   214  	// Strip time and pid prefix.
   215  	actual = regexp.MustCompile(`(?m)^.* testinglogger_test.go:`).ReplaceAllString(actual, `testinglogger_test.go:`)
   216  
   217  	// Strip duration.
   218  	actual = regexp.MustCompile(`timeSinceCompletion="\d+s"`).ReplaceAllString(actual, `timeSinceCompletion="<...>s"`)
   219  
   220  	// All lines from the callstack get stripped. We can be sure that it was non-empty because otherwise we wouldn't
   221  	// have the < > markers.
   222  	//
   223  	// Full output:
   224  	// 	testinglogger_test.go:194] "WARNING: test kept at least one goroutine running after test completion" logger="TestStop/Sub leaked goroutine.me" completed=true timeSinceCompletion="15s" callstack=<
   225  	//        	goroutine 23 [running]:
   226  	//        	k8s.io/klog/v2/internal/dbg.Stacks(0x0)
   227  	//        		/nvme/gopath/src/k8s.io/klog/internal/dbg/dbg.go:34 +0x8a
   228  	//        	k8s.io/klog/v2/ktesting.tlogger.fallbackLogger({0xc0000f2780, {0x0, 0x0}, {0x0, 0x0, 0x0}})
   229  	//        		/nvme/gopath/src/k8s.io/klog/ktesting/testinglogger.go:292 +0x232
   230  	//        	k8s.io/klog/v2/ktesting.tlogger.Info({0xc0000f2780, {0x0, 0x0}, {0x0, 0x0, 0x0}}, 0x0, {0x5444a5, 0x13}, {0x0, ...})
   231  	//        		/nvme/gopath/src/k8s.io/klog/ktesting/testinglogger.go:316 +0x28a
   232  	//        	github.com/go-logr/logr.Logger.Info({{0x572438?, 0xc0000c0ff0?}, 0x0?}, {0x5444a5, 0x13}, {0x0, 0x0, 0x0})
   233  	//        		/nvme/gopath/pkg/mod/github.com/go-logr/logr@v1.2.0/logr.go:249 +0xd0
   234  	//        	k8s.io/klog/v2/ktesting_test.TestStop.func1.1()
   235  	//        		/nvme/gopath/src/k8s.io/klog/ktesting/testinglogger_test.go:194 +0xe5
   236  	//        	created by k8s.io/klog/v2/ktesting_test.TestStop.func1
   237  	//        		/nvme/gopath/src/k8s.io/klog/ktesting/testinglogger_test.go:185 +0x105
   238  	//         >
   239  	actual = regexp.MustCompile(`(?m)^\t.*?\n`).ReplaceAllString(actual, ``)
   240  
   241  	expected := fmt.Sprintf(`testinglogger_test.go:%d] "simple info message" logger="TestStop/Sub leaked goroutine"
   242  testinglogger_test.go:%d] "error message" logger="TestStop/Sub leaked goroutine"
   243  testinglogger_test.go:%d] "WARNING: test kept at least one goroutine running after test completion" logger="TestStop/Sub leaked goroutine.me" completed=true timeSinceCompletion="<...>s" callstack=<
   244   >
   245  testinglogger_test.go:%d] "complex info message" logger="TestStop/Sub leaked goroutine.me" completed=true anotherValue=1
   246  `,
   247  		line+1, line+2, line+4, line+4)
   248  	if actual != expected {
   249  		t.Errorf("Output does not match. Expected:\n%s\nActual:\n%s\n", expected, actual)
   250  	}
   251  
   252  	testingLogger, ok := logger.GetSink().(ktesting.Underlier)
   253  	if !ok {
   254  		t.Fatal("should have had a ktesting logger")
   255  	}
   256  	captured := testingLogger.GetBuffer().String()
   257  	if captured != "" {
   258  		t.Errorf("testing logger should not have captured any output, got instead:\n%s", captured)
   259  	}
   260  }
   261
View as plain text