Source file src/k8s.io/klog/v2/test/output.go

Documentation: k8s.io/klog/v2/test

     1  /*
     2  Copyright 2021 The Kubernetes Authors.
     3  
     4  Licensed under the Apache License, Version 2.0 (the "License");
     5  you may not use this file except in compliance with the License.
     6  You may obtain a copy of the License at
     7  
     8      http://www.apache.org/licenses/LICENSE-2.0
     9  
    10  Unless required by applicable law or agreed to in writing, software
    11  distributed under the License is distributed on an "AS IS" BASIS,
    12  WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
    13  See the License for the specific language governing permissions and
    14  limitations under the License.
    15  */
    16  
    17  // Package test contains a reusable unit test for logging output and behavior.
    18  package test
    19  
    20  import (
    21  	"bytes"
    22  	"encoding/json"
    23  	"errors"
    24  	"flag"
    25  	"fmt"
    26  	"io"
    27  	"regexp"
    28  	"runtime"
    29  	"strconv"
    30  	"strings"
    31  	"testing"
    32  	"time"
    33  
    34  	"github.com/go-logr/logr"
    35  
    36  	"k8s.io/klog/v2"
    37  	"k8s.io/klog/v2/textlogger"
    38  )
    39  
    40  // InitKlog must be called in a test to configure klog for testing.
    41  // The previous klog configuration will be restored automatically
    42  // after the test.
    43  //
    44  // The returned flag set has the klog flags registered. It can
    45  // be used to make further changes to the klog configuration.
    46  func InitKlog(tb testing.TB) *flag.FlagSet {
    47  	state := klog.CaptureState()
    48  	tb.Cleanup(state.Restore)
    49  
    50  	expectNoError := func(err error) {
    51  		if err != nil {
    52  			tb.Fatalf("unexpected error: %v", err)
    53  		}
    54  	}
    55  
    56  	// klog gets configured so that it writes to a single output file that
    57  	// will be set during tests with SetOutput.
    58  	var fs flag.FlagSet
    59  	klog.InitFlags(&fs)
    60  	expectNoError(fs.Set("v", "10"))
    61  	expectNoError(fs.Set("log_file", "/dev/null"))
    62  	expectNoError(fs.Set("logtostderr", "false"))
    63  	expectNoError(fs.Set("alsologtostderr", "false"))
    64  	expectNoError(fs.Set("stderrthreshold", "10"))
    65  
    66  	return &fs
    67  }
    68  
    69  // OutputConfig contains optional settings for Output.
    70  type OutputConfig struct {
    71  	// NewLogger is called to create a new logger. If nil, output via klog
    72  	// is tested. Support for -vmodule is optional.  ClearLogger is called
    73  	// after each test, therefore it is okay to user SetLogger without
    74  	// undoing that in the callback.
    75  	NewLogger func(out io.Writer, v int, vmodule string) logr.Logger
    76  
    77  	// AsBackend enables testing through klog and the logger set there with
    78  	// SetLogger.
    79  	AsBackend bool
    80  
    81  	// ExpectedOutputMapping replaces the builtin expected output for test
    82  	// cases with something else. If nil or a certain case is not present,
    83  	// the original text is used.
    84  	//
    85  	// The expected output uses <LINE> as a placeholder for the line of the
    86  	// log call. The source code is always the output.go file itself. When
    87  	// testing a logger directly, <WITH-VALUES-LINE> is used for the first
    88  	// WithValues call, <WITH-VALUES-LINE-2> for a second and
    89  	// <WITH-VALUES-LINE-3> for a third.
    90  	ExpectedOutputMapping map[string]string
    91  
    92  	// SupportsVModule indicates that the logger supports the vmodule
    93  	// parameter. Ignored when logging through klog.
    94  	SupportsVModule bool
    95  }
    96  
    97  type testcase struct {
    98  	withHelper bool // use wrappers that get skipped during stack unwinding
    99  	withNames  []string
   100  	// For a first WithValues call: logger1 := logger.WithValues()
   101  	withValues []interface{}
   102  	// For another WithValues call: logger2 := logger1.WithValues()
   103  	moreValues []interface{}
   104  	// For another WithValues call on the same logger as before: logger3 := logger1.WithValues()
   105  	evenMoreValues []interface{}
   106  	v              int
   107  	vmodule        string
   108  	text           string
   109  	values         []interface{}
   110  	err            error
   111  	expectedOutput string
   112  }
   113  
   114  var tests = map[string]testcase{
   115  	"log with values": {
   116  		text:   "test",
   117  		values: []interface{}{"akey", "avalue"},
   118  		expectedOutput: `I output.go:<LINE>] "test" akey="avalue"
   119  `,
   120  	},
   121  	"call depth": {
   122  		text:       "helper",
   123  		withHelper: true,
   124  		values:     []interface{}{"akey", "avalue"},
   125  		expectedOutput: `I output.go:<LINE>] "helper" akey="avalue"
   126  `,
   127  	},
   128  	"verbosity enabled": {
   129  		text: "you see me",
   130  		v:    9,
   131  		expectedOutput: `I output.go:<LINE>] "you see me"
   132  `,
   133  	},
   134  	"verbosity disabled": {
   135  		text: "you don't see me",
   136  		v:    11,
   137  	},
   138  	"vmodule": {
   139  		text:    "v=11: you see me because of -vmodule output=11",
   140  		v:       11,
   141  		vmodule: "output=11",
   142  		expectedOutput: `I output.go:<LINE>] "v=11: you see me because of -vmodule output=11"
   143  `,
   144  	},
   145  	"other vmodule": {
   146  		text:    "v=11: you still don't see me because of -vmodule output_helper=11",
   147  		v:       11,
   148  		vmodule: "output_helper=11",
   149  	},
   150  	"vmodule with helper": {
   151  		text:       "v=11: you see me because of -vmodule output=11",
   152  		withHelper: true,
   153  		v:          11,
   154  		vmodule:    "output=11",
   155  		expectedOutput: `I output.go:<LINE>] "v=11: you see me because of -vmodule output=11"
   156  `,
   157  	},
   158  	"other vmodule with helper": {
   159  		text:       "v=11: you still don't see me because of -vmodule output_helper=11",
   160  		withHelper: true,
   161  		v:          11,
   162  		vmodule:    "output_helper=11",
   163  	},
   164  	"log with name and values": {
   165  		withNames: []string{"me"},
   166  		text:      "test",
   167  		values:    []interface{}{"akey", "avalue"},
   168  		expectedOutput: `I output.go:<LINE>] "test" logger="me" akey="avalue"
   169  `,
   170  	},
   171  	"log with multiple names and values": {
   172  		withNames: []string{"hello", "world"},
   173  		text:      "test",
   174  		values:    []interface{}{"akey", "avalue"},
   175  		expectedOutput: `I output.go:<LINE>] "test" logger="hello.world" akey="avalue"
   176  `,
   177  	},
   178  	"override single value": {
   179  		withValues: []interface{}{"akey", "avalue"},
   180  		text:       "test",
   181  		values:     []interface{}{"akey", "avalue2"},
   182  		expectedOutput: `I output.go:<LINE>] "test" akey="avalue2"
   183  `,
   184  	},
   185  	"override WithValues": {
   186  		withValues: []interface{}{"duration", time.Hour, "X", "y"},
   187  		text:       "test",
   188  		values:     []interface{}{"duration", time.Minute, "A", "b"},
   189  		expectedOutput: `I output.go:<LINE>] "test" X="y" duration="1m0s" A="b"
   190  `,
   191  	},
   192  	"odd WithValues": {
   193  		withValues: []interface{}{"keyWithoutValue"},
   194  		moreValues: []interface{}{"anotherKeyWithoutValue"},
   195  		text:       "odd WithValues",
   196  		expectedOutput: `I output.go:<LINE>] "odd WithValues" keyWithoutValue="(MISSING)"
   197  I output.go:<LINE>] "odd WithValues" keyWithoutValue="(MISSING)" anotherKeyWithoutValue="(MISSING)"
   198  I output.go:<LINE>] "odd WithValues" keyWithoutValue="(MISSING)"
   199  `,
   200  	},
   201  	"multiple WithValues": {
   202  		withValues:     []interface{}{"firstKey", 1},
   203  		moreValues:     []interface{}{"secondKey", 2},
   204  		evenMoreValues: []interface{}{"secondKey", 3},
   205  		text:           "test",
   206  		expectedOutput: `I output.go:<LINE>] "test" firstKey=1
   207  I output.go:<LINE>] "test" firstKey=1 secondKey=2
   208  I output.go:<LINE>] "test" firstKey=1
   209  I output.go:<LINE>] "test" firstKey=1 secondKey=3
   210  `,
   211  	},
   212  	"empty WithValues": {
   213  		withValues: []interface{}{},
   214  		text:       "test",
   215  		expectedOutput: `I output.go:<LINE>] "test"
   216  `,
   217  	},
   218  	"print duplicate keys in arguments": {
   219  		text:   "test",
   220  		values: []interface{}{"akey", "avalue", "akey", "avalue2"},
   221  		expectedOutput: `I output.go:<LINE>] "test" akey="avalue" akey="avalue2"
   222  `,
   223  	},
   224  	"preserve order of key/value pairs": {
   225  		withValues: []interface{}{"akey9", "avalue9", "akey8", "avalue8", "akey1", "avalue1"},
   226  		text:       "test",
   227  		values:     []interface{}{"akey5", "avalue5", "akey4", "avalue4"},
   228  		expectedOutput: `I output.go:<LINE>] "test" akey9="avalue9" akey8="avalue8" akey1="avalue1" akey5="avalue5" akey4="avalue4"
   229  `,
   230  	},
   231  	"handle odd-numbers of KVs": {
   232  		text:   "odd arguments",
   233  		values: []interface{}{"akey", "avalue", "akey2"},
   234  		expectedOutput: `I output.go:<LINE>] "odd arguments" akey="avalue" akey2="(MISSING)"
   235  `,
   236  	},
   237  	"html characters": {
   238  		text:   "test",
   239  		values: []interface{}{"akey", "<&>"},
   240  		expectedOutput: `I output.go:<LINE>] "test" akey="<&>"
   241  `,
   242  	},
   243  	"quotation": {
   244  		text:   `"quoted"`,
   245  		values: []interface{}{"key", `"quoted value"`},
   246  		expectedOutput: `I output.go:<LINE>] "\"quoted\"" key="\"quoted value\""
   247  `,
   248  	},
   249  	"handle odd-numbers of KVs in both log values and Info args": {
   250  		withValues: []interface{}{"basekey1", "basevar1", "basekey2"},
   251  		text:       "both odd",
   252  		values:     []interface{}{"akey", "avalue", "akey2"},
   253  		expectedOutput: `I output.go:<LINE>] "both odd" basekey1="basevar1" basekey2="(MISSING)" akey="avalue" akey2="(MISSING)"
   254  `,
   255  	},
   256  	"KObj": {
   257  		text:   "test",
   258  		values: []interface{}{"pod", klog.KObj(&kmeta{Name: "pod-1", Namespace: "kube-system"})},
   259  		expectedOutput: `I output.go:<LINE>] "test" pod="kube-system/pod-1"
   260  `,
   261  	},
   262  	"KObjs": {
   263  		text: "KObjs",
   264  		values: []interface{}{"pods",
   265  			klog.KObjs([]interface{}{
   266  				&kmeta{Name: "pod-1", Namespace: "kube-system"},
   267  				&kmeta{Name: "pod-2", Namespace: "kube-system"},
   268  			})},
   269  		expectedOutput: `I output.go:<LINE>] "KObjs" pods=[{"name":"pod-1","namespace":"kube-system"},{"name":"pod-2","namespace":"kube-system"}]
   270  `,
   271  	},
   272  	"KObjSlice okay": {
   273  		text: "KObjSlice",
   274  		values: []interface{}{"pods",
   275  			klog.KObjSlice([]interface{}{
   276  				&kmeta{Name: "pod-1", Namespace: "kube-system"},
   277  				&kmeta{Name: "pod-2", Namespace: "kube-system"},
   278  			})},
   279  		expectedOutput: `I output.go:<LINE>] "KObjSlice" pods=["kube-system/pod-1","kube-system/pod-2"]
   280  `,
   281  	},
   282  	"KObjSlice nil arg": {
   283  		text: "test",
   284  		values: []interface{}{"pods",
   285  			klog.KObjSlice(nil)},
   286  		expectedOutput: `I output.go:<LINE>] "test" pods=null
   287  `,
   288  	},
   289  	"KObjSlice int arg": {
   290  		text: "test",
   291  		values: []interface{}{"pods",
   292  			klog.KObjSlice(1)},
   293  		expectedOutput: `I output.go:<LINE>] "test" pods="<KObjSlice needs a slice, got type int>"
   294  `,
   295  	},
   296  	"KObjSlice nil entry": {
   297  		text: "test",
   298  		values: []interface{}{"pods",
   299  			klog.KObjSlice([]interface{}{
   300  				&kmeta{Name: "pod-1", Namespace: "kube-system"},
   301  				nil,
   302  			})},
   303  		expectedOutput: `I output.go:<LINE>] "test" pods=["kube-system/pod-1",null]
   304  `,
   305  	},
   306  	"KObjSlice ints": {
   307  		text: "test",
   308  		values: []interface{}{"ints",
   309  			klog.KObjSlice([]int{1, 2, 3})},
   310  		expectedOutput: `I output.go:<LINE>] "test" ints=["<KObjSlice needs a slice of values implementing KMetadata, got type int>"]
   311  `,
   312  	},
   313  	"regular error types as value": {
   314  		text:   "test",
   315  		values: []interface{}{"err", errors.New("whoops")},
   316  		expectedOutput: `I output.go:<LINE>] "test" err="whoops"
   317  `,
   318  	},
   319  	"ignore MarshalJSON": {
   320  		text:   "test",
   321  		values: []interface{}{"err", &customErrorJSON{"whoops"}},
   322  		expectedOutput: `I output.go:<LINE>] "test" err="whoops"
   323  `,
   324  	},
   325  	"regular error types when using logr.Error": {
   326  		text: "test",
   327  		err:  errors.New("whoops"),
   328  		expectedOutput: `E output.go:<LINE>] "test" err="whoops"
   329  `,
   330  	},
   331  	"Error() for nil": {
   332  		text: "error nil",
   333  		err:  (*customErrorJSON)(nil),
   334  		expectedOutput: `E output.go:<LINE>] "error nil" err="<panic: runtime error: invalid memory address or nil pointer dereference>"
   335  `,
   336  	},
   337  	"String() for nil": {
   338  		text:   "stringer nil",
   339  		values: []interface{}{"stringer", (*stringer)(nil)},
   340  		expectedOutput: `I output.go:<LINE>] "stringer nil" stringer="<panic: runtime error: invalid memory address or nil pointer dereference>"
   341  `,
   342  	},
   343  	"MarshalLog() for nil": {
   344  		text:   "marshaler nil",
   345  		values: []interface{}{"obj", (*klog.ObjectRef)(nil)},
   346  		expectedOutput: `I output.go:<LINE>] "marshaler nil" obj="<panic: value method k8s.io/klog/v2.ObjectRef.WriteText called using nil *ObjectRef pointer>"
   347  `,
   348  	},
   349  	"Error() that panics": {
   350  		text: "error panic",
   351  		err:  faultyError{},
   352  		expectedOutput: `E output.go:<LINE>] "error panic" err="<panic: fake Error panic>"
   353  `,
   354  	},
   355  	"String() that panics": {
   356  		text:   "stringer panic",
   357  		values: []interface{}{"stringer", faultyStringer{}},
   358  		expectedOutput: `I output.go:<LINE>] "stringer panic" stringer="<panic: fake String panic>"
   359  `,
   360  	},
   361  	"MarshalLog() that panics": {
   362  		text:   "marshaler panic",
   363  		values: []interface{}{"obj", faultyMarshaler{}},
   364  		expectedOutput: `I output.go:<LINE>] "marshaler panic" obj="<panic: fake MarshalLog panic>"
   365  `,
   366  	},
   367  	"MarshalLog() that returns itself": {
   368  		text:   "marshaler recursion",
   369  		values: []interface{}{"obj", recursiveMarshaler{}},
   370  		expectedOutput: `I output.go:<LINE>] "marshaler recursion" obj={}
   371  `,
   372  	},
   373  	"handle integer keys": {
   374  		withValues: []interface{}{1, "value", 2, "value2"},
   375  		text:       "integer keys",
   376  		values:     []interface{}{"akey", "avalue", "akey2"},
   377  		expectedOutput: `I output.go:<LINE>] "integer keys" %!s(int=1)="value" %!s(int=2)="value2" akey="avalue" akey2="(MISSING)"
   378  `,
   379  	},
   380  	"struct keys": {
   381  		withValues: []interface{}{struct{ name string }{"name"}, "value", "test", "other value"},
   382  		text:       "struct keys",
   383  		values:     []interface{}{"key", "val"},
   384  		expectedOutput: `I output.go:<LINE>] "struct keys" {name}="value" test="other value" key="val"
   385  `,
   386  	},
   387  	"map keys": {
   388  		withValues: []interface{}{},
   389  		text:       "map keys",
   390  		values:     []interface{}{map[string]bool{"test": true}, "test"},
   391  		expectedOutput: `I output.go:<LINE>] "map keys" map[test:%!s(bool=true)]="test"
   392  `,
   393  	},
   394  	"map values": {
   395  		text:   "maps",
   396  		values: []interface{}{"s", map[string]string{"hello": "world"}, "i", map[int]int{1: 2, 3: 4}},
   397  		expectedOutput: `I output.go:<LINE>] "maps" s={"hello":"world"} i={"1":2,"3":4}
   398  `,
   399  	},
   400  	"slice values": {
   401  		text:   "slices",
   402  		values: []interface{}{"s", []string{"hello", "world"}, "i", []int{1, 2, 3}},
   403  		expectedOutput: `I output.go:<LINE>] "slices" s=["hello","world"] i=[1,2,3]
   404  `,
   405  	},
   406  	"struct values": {
   407  		text:   "structs",
   408  		values: []interface{}{"s", struct{ Name, Kind, hidden string }{Name: "worker", Kind: "pod", hidden: "ignore"}},
   409  		expectedOutput: `I output.go:<LINE>] "structs" s={"Name":"worker","Kind":"pod"}
   410  `,
   411  	},
   412  	"klog.Format": {
   413  		text:   "klog.Format",
   414  		values: []interface{}{"s", klog.Format(struct{ Name, Kind, hidden string }{Name: "worker", Kind: "pod", hidden: "ignore"})},
   415  		expectedOutput: `I output.go:<LINE>] "klog.Format" s=<
   416  	{
   417  	  "Name": "worker",
   418  	  "Kind": "pod"
   419  	}
   420   >
   421  `,
   422  	},
   423  	"cyclic list": {
   424  		text:   "cycle",
   425  		values: []interface{}{"list", newCyclicList()},
   426  		expectedOutput: `I output.go:<LINE>] "cycle" list="<internal error: json: unsupported value: encountered a cycle via *test.myList>"
   427  `,
   428  	},
   429  }
   430  
   431  func printWithLogger(logger logr.Logger, test testcase) {
   432  	for _, name := range test.withNames {
   433  		logger = logger.WithName(name)
   434  	}
   435  	// When we have multiple WithValues calls, we test
   436  	// first with the initial set of additional values, then
   437  	// the combination, then again the original logger.
   438  	// It must not have been modified. This produces
   439  	// three log entries.
   440  	logger = logger.WithValues(test.withValues...) // <WITH-VALUES>
   441  	loggers := []logr.Logger{logger}
   442  	if test.moreValues != nil {
   443  		loggers = append(loggers, logger.WithValues(test.moreValues...), logger) // <WITH-VALUES-2>
   444  	}
   445  	if test.evenMoreValues != nil {
   446  		loggers = append(loggers, logger.WithValues(test.evenMoreValues...)) // <WITH-VALUES-3>
   447  	}
   448  	for _, logger := range loggers {
   449  		if test.withHelper {
   450  			loggerHelper(logger.V(test.v), test.text, test.values) // <LINE>
   451  		} else if test.err != nil {
   452  			logger.Error(test.err, test.text, test.values...) // <LINE>
   453  		} else {
   454  			logger.V(test.v).Info(test.text, test.values...) // <LINE>
   455  		}
   456  	}
   457  }
   458  
   459  var _, _, printWithLoggerLine, _ = runtime.Caller(0) // anchor for finding the line numbers above
   460  
   461  func initPrintWithKlog(tb testing.TB, test testcase) {
   462  	if test.withHelper && test.vmodule != "" {
   463  		tb.Skip("klog does not support -vmodule properly when using helper functions")
   464  	}
   465  
   466  	state := klog.CaptureState()
   467  	tb.Cleanup(state.Restore)
   468  
   469  	var fs flag.FlagSet
   470  	klog.InitFlags(&fs)
   471  	if err := fs.Set("v", "10"); err != nil {
   472  		tb.Fatalf("unexpected error: %v", err)
   473  	}
   474  	if err := fs.Set("vmodule", test.vmodule); err != nil {
   475  		tb.Fatalf("unexpected error: %v", err)
   476  	}
   477  }
   478  
   479  func printWithKlog(test testcase) {
   480  	kv := []interface{}{}
   481  	haveKeyInValues := func(key interface{}) bool {
   482  		for i := 0; i < len(test.values); i += 2 {
   483  			if key == test.values[i] {
   484  				return true
   485  			}
   486  		}
   487  		return false
   488  	}
   489  	appendKV := func(withValues ...interface{}) {
   490  		if len(withValues)%2 != 0 {
   491  			withValues = append(withValues, "(MISSING)")
   492  		}
   493  		for i := 0; i < len(withValues); i += 2 {
   494  			if !haveKeyInValues(withValues[i]) {
   495  				kv = append(kv, withValues[i], withValues[i+1])
   496  			}
   497  		}
   498  	}
   499  	// Here we need to emulate the handling of WithValues above.
   500  	if len(test.withNames) > 0 {
   501  		appendKV("logger", strings.Join(test.withNames, "."))
   502  	}
   503  	appendKV(test.withValues...)
   504  	kvs := [][]interface{}{copySlice(kv)}
   505  	if test.moreValues != nil {
   506  		appendKV(test.moreValues...)
   507  		kvs = append(kvs, copySlice(kv), copySlice(kvs[0]))
   508  	}
   509  	if test.evenMoreValues != nil {
   510  		kv = copySlice(kvs[0])
   511  		appendKV(test.evenMoreValues...)
   512  		kvs = append(kvs, copySlice(kv))
   513  	}
   514  	for _, kv := range kvs {
   515  		if len(test.values) > 0 {
   516  			kv = append(kv, test.values...)
   517  		}
   518  		text := test.text
   519  		if test.withHelper {
   520  			klogHelper(klog.Level(test.v), text, kv)
   521  		} else if test.err != nil {
   522  			klog.ErrorS(test.err, text, kv...)
   523  		} else {
   524  			klog.V(klog.Level(test.v)).InfoS(text, kv...)
   525  		}
   526  	}
   527  }
   528  
   529  var _, _, printWithKlogLine, _ = runtime.Caller(0) // anchor for finding the line numbers above
   530  
   531  // Output covers various special cases of emitting log output.
   532  // It can be used for arbitrary logr.Logger implementations.
   533  //
   534  // The expected output is what klog would print. When testing loggers
   535  // that emit different output, a mapping from klog output to the
   536  // corresponding logger output must be provided, otherwise the
   537  // test will compare against the expected klog output.
   538  //
   539  // Loggers will be tested with direct calls to Info or
   540  // as backend for klog.
   541  func Output(t *testing.T, config OutputConfig) {
   542  	for n, test := range tests {
   543  		t.Run(n, func(t *testing.T) {
   544  			initPrintWithKlog(t, test)
   545  
   546  			testOutput := func(t *testing.T, expectedLine int, print func(buffer *bytes.Buffer)) {
   547  				var tmpWriteBuffer bytes.Buffer
   548  				klog.SetOutput(&tmpWriteBuffer)
   549  				print(&tmpWriteBuffer)
   550  				klog.Flush()
   551  
   552  				actual := tmpWriteBuffer.String()
   553  				// Strip varying header.
   554  				re := `(?m)^(.).... ..:..:......... ....... output.go`
   555  				actual = regexp.MustCompile(re).ReplaceAllString(actual, `${1} output.go`)
   556  
   557  				// Inject expected line. This matches the if checks above, which are
   558  				// the same for both printWithKlog and printWithLogger.
   559  				callLine := expectedLine
   560  				if test.withHelper {
   561  					callLine -= 8
   562  				} else if test.err != nil {
   563  					callLine -= 6
   564  				} else {
   565  					callLine -= 4
   566  				}
   567  				expected := test.expectedOutput
   568  				if repl, ok := config.ExpectedOutputMapping[expected]; ok {
   569  					expected = repl
   570  				}
   571  				expectedWithPlaceholder := expected
   572  				expected = strings.ReplaceAll(expected, "<LINE>", fmt.Sprintf("%d", callLine))
   573  				expected = strings.ReplaceAll(expected, "<WITH-VALUES>", fmt.Sprintf("%d", expectedLine-18))
   574  				expected = strings.ReplaceAll(expected, "<WITH-VALUES-2>", fmt.Sprintf("%d", expectedLine-15))
   575  				expected = strings.ReplaceAll(expected, "<WITH-VALUES-3>", fmt.Sprintf("%d", expectedLine-12))
   576  				if actual != expected {
   577  					if expectedWithPlaceholder == test.expectedOutput {
   578  						t.Errorf("Output mismatch. Expected:\n%s\nActual:\n%s\n", expectedWithPlaceholder, actual)
   579  					} else {
   580  						t.Errorf("Output mismatch. klog:\n%s\nExpected:\n%s\nActual:\n%s\n", test.expectedOutput, expectedWithPlaceholder, actual)
   581  					}
   582  				}
   583  			}
   584  
   585  			if config.NewLogger == nil {
   586  				// Test klog.
   587  				testOutput(t, printWithKlogLine-1, func(_ *bytes.Buffer) {
   588  					printWithKlog(test)
   589  				})
   590  				return
   591  			}
   592  
   593  			if config.AsBackend {
   594  				testOutput(t, printWithKlogLine-1, func(buffer *bytes.Buffer) {
   595  					setLogger(config.NewLogger(buffer, 10, test.vmodule))
   596  					printWithKlog(test)
   597  				})
   598  				return
   599  			}
   600  
   601  			if test.vmodule != "" && !config.SupportsVModule {
   602  				t.Skip("vmodule not supported")
   603  			}
   604  
   605  			testOutput(t, printWithLoggerLine-1, func(buffer *bytes.Buffer) {
   606  				printWithLogger(config.NewLogger(buffer, 10, test.vmodule), test)
   607  			})
   608  		})
   609  	}
   610  
   611  	if config.NewLogger == nil || config.AsBackend {
   612  		configStruct := klog.Format(myConfig{typeMeta: typeMeta{Kind: "config"}, RealField: 42})
   613  		configStructOutput := `I output.go:<LINE>] "Format" config=<
   614  	{
   615  	  "Kind": "config",
   616  	  "RealField": 42
   617  	}
   618   >
   619  `
   620  
   621  		// Test all klog output functions.
   622  		//
   623  		// Each test case must be defined with the same number of
   624  		// lines, then the source code location of the call itself
   625  		// can be computed below.
   626  		tests := []struct {
   627  			name    string
   628  			logFunc func()
   629  			output  string
   630  		}{
   631  			{
   632  				name:    "Info",
   633  				logFunc: func() { klog.Info("hello", "world") },
   634  				output:  "I output.go:<LINE>] helloworld\n", // This looks odd, but simply is how klog works.
   635  			},
   636  			{
   637  				name:    "InfoDepth",
   638  				logFunc: func() { klog.InfoDepth(0, "hello", "world") },
   639  				output:  "I output.go:<LINE>] helloworld\n",
   640  			},
   641  			{
   642  				name:    "Infoln",
   643  				logFunc: func() { klog.Infoln("hello", "world") },
   644  				output:  "I output.go:<LINE>] hello world\n",
   645  			},
   646  			{
   647  				name:    "InfolnDepth",
   648  				logFunc: func() { klog.InfolnDepth(0, "hello", "world") },
   649  				output:  "I output.go:<LINE>] hello world\n",
   650  			},
   651  			{
   652  				name:    "Infof",
   653  				logFunc: func() { klog.Infof("hello %s", "world") },
   654  				output:  "I output.go:<LINE>] hello world\n",
   655  			},
   656  			{
   657  				name:    "InfofDepth",
   658  				logFunc: func() { klog.InfofDepth(0, "hello %s", "world") },
   659  				output:  "I output.go:<LINE>] hello world\n",
   660  			},
   661  			{
   662  				name:    "InfoS",
   663  				logFunc: func() { klog.InfoS("hello", "what", "world") },
   664  				output:  "I output.go:<LINE>] \"hello\" what=\"world\"\n",
   665  			},
   666  			{
   667  				name:    "InfoSDepth",
   668  				logFunc: func() { klog.InfoSDepth(0, "hello", "what", "world") },
   669  				output:  "I output.go:<LINE>] \"hello\" what=\"world\"\n",
   670  			},
   671  			{
   672  				name:    "Warning",
   673  				logFunc: func() { klog.Warning("hello", "world") },
   674  				output:  "W output.go:<LINE>] helloworld\n",
   675  			},
   676  			{
   677  				name:    "WarningDepth",
   678  				logFunc: func() { klog.WarningDepth(0, "hello", "world") },
   679  				output:  "W output.go:<LINE>] helloworld\n",
   680  			},
   681  			{
   682  				name:    "Warningln",
   683  				logFunc: func() { klog.Warningln("hello", "world") },
   684  				output:  "W output.go:<LINE>] hello world\n",
   685  			},
   686  			{
   687  				name:    "WarninglnDepth",
   688  				logFunc: func() { klog.WarninglnDepth(0, "hello", "world") },
   689  				output:  "W output.go:<LINE>] hello world\n",
   690  			},
   691  			{
   692  				name:    "Warningf",
   693  				logFunc: func() { klog.Warningf("hello %s", "world") },
   694  				output:  "W output.go:<LINE>] hello world\n",
   695  			},
   696  			{
   697  				name:    "WarningfDepth",
   698  				logFunc: func() { klog.WarningfDepth(0, "hello %s", "world") },
   699  				output:  "W output.go:<LINE>] hello world\n",
   700  			},
   701  			{
   702  				name:    "Error",
   703  				logFunc: func() { klog.Error("hello", "world") },
   704  				output:  "E output.go:<LINE>] helloworld\n",
   705  			},
   706  			{
   707  				name:    "ErrorDepth",
   708  				logFunc: func() { klog.ErrorDepth(0, "hello", "world") },
   709  				output:  "E output.go:<LINE>] helloworld\n",
   710  			},
   711  			{
   712  				name:    "Errorln",
   713  				logFunc: func() { klog.Errorln("hello", "world") },
   714  				output:  "E output.go:<LINE>] hello world\n",
   715  			},
   716  			{
   717  				name:    "ErrorlnDepth",
   718  				logFunc: func() { klog.ErrorlnDepth(0, "hello", "world") },
   719  				output:  "E output.go:<LINE>] hello world\n",
   720  			},
   721  			{
   722  				name:    "Errorf",
   723  				logFunc: func() { klog.Errorf("hello %s", "world") },
   724  				output:  "E output.go:<LINE>] hello world\n",
   725  			},
   726  			{
   727  				name:    "ErrorfDepth",
   728  				logFunc: func() { klog.ErrorfDepth(0, "hello %s", "world") },
   729  				output:  "E output.go:<LINE>] hello world\n",
   730  			},
   731  			{
   732  				name:    "ErrorS",
   733  				logFunc: func() { klog.ErrorS(errors.New("hello"), "world") },
   734  				output:  "E output.go:<LINE>] \"world\" err=\"hello\"\n",
   735  			},
   736  			{
   737  				name:    "ErrorSDepth",
   738  				logFunc: func() { klog.ErrorSDepth(0, errors.New("hello"), "world") },
   739  				output:  "E output.go:<LINE>] \"world\" err=\"hello\"\n",
   740  			},
   741  			{
   742  				name:    "V().Info",
   743  				logFunc: func() { klog.V(1).Info("hello", "one", "world") },
   744  				output:  "I output.go:<LINE>] hellooneworld\n",
   745  			},
   746  			{
   747  				name:    "V().InfoDepth",
   748  				logFunc: func() { klog.V(1).InfoDepth(0, "hello", "one", "world") },
   749  				output:  "I output.go:<LINE>] hellooneworld\n",
   750  			},
   751  			{
   752  				name:    "V().Infoln",
   753  				logFunc: func() { klog.V(1).Infoln("hello", "one", "world") },
   754  				output:  "I output.go:<LINE>] hello one world\n",
   755  			},
   756  			{
   757  				name:    "V().InfolnDepth",
   758  				logFunc: func() { klog.V(1).InfolnDepth(0, "hello", "one", "world") },
   759  				output:  "I output.go:<LINE>] hello one world\n",
   760  			},
   761  			{
   762  				name:    "V().Infof",
   763  				logFunc: func() { klog.V(1).Infof("hello %s %s", "one", "world") },
   764  				output:  "I output.go:<LINE>] hello one world\n",
   765  			},
   766  			{
   767  				name:    "V().InfofDepth",
   768  				logFunc: func() { klog.V(1).InfofDepth(0, "hello %s %s", "one", "world") },
   769  				output:  "I output.go:<LINE>] hello one world\n",
   770  			},
   771  			{
   772  				name:    "V().InfoS",
   773  				logFunc: func() { klog.V(1).InfoS("hello", "what", "one world") },
   774  				output:  "I output.go:<LINE>] \"hello\" what=\"one world\"\n",
   775  			},
   776  			{
   777  				name:    "V().InfoSDepth",
   778  				logFunc: func() { klog.V(1).InfoSDepth(0, "hello", "what", "one world") },
   779  				output:  "I output.go:<LINE>] \"hello\" what=\"one world\"\n",
   780  			},
   781  			{
   782  				name:    "V().ErrorS",
   783  				logFunc: func() { klog.V(1).ErrorS(errors.New("hello"), "one world") },
   784  				output:  "E output.go:<LINE>] \"one world\" err=\"hello\"\n",
   785  			},
   786  			{
   787  				name:    "Format InfoS",
   788  				logFunc: func() { klog.InfoS("Format", "config", configStruct) },
   789  				output:  configStructOutput,
   790  			},
   791  		}
   792  		_, _, line, _ := runtime.Caller(0)
   793  
   794  		for i, test := range tests {
   795  			t.Run(test.name, func(t *testing.T) {
   796  				var buffer bytes.Buffer
   797  				haveWriteKlogBuffer := false
   798  				if config.NewLogger == nil {
   799  					klog.SetOutput(&buffer)
   800  				} else {
   801  					haveWriteKlogBuffer = setLogger(config.NewLogger(&buffer, 10, ""))
   802  					defer klog.ClearLogger()
   803  				}
   804  				test.logFunc()
   805  				klog.Flush()
   806  
   807  				actual := buffer.String()
   808  				// Strip varying header.
   809  				re := `(?m)^(.).... ..:..:......... ....... output.go`
   810  				actual = regexp.MustCompile(re).ReplaceAllString(actual, `${1} output.go`)
   811  
   812  				// Inject expected line. This matches the if checks above, which are
   813  				// the same for both printWithKlog and printWithLogger.
   814  				callLine := line + 1 - (len(tests)-i)*5
   815  				expected := test.output
   816  
   817  				// When klog does string formating for
   818  				// non-structured calls, it passes the entire
   819  				// result, including a trailing newline, to
   820  				// Logger.Info.
   821  				if config.NewLogger != nil &&
   822  					!haveWriteKlogBuffer &&
   823  					!strings.HasSuffix(test.name, "S") &&
   824  					!strings.HasSuffix(test.name, "SDepth") {
   825  					// klog: I output.go:<LINE>] hello world
   826  					// with logger: I output.go:<LINE>] "hello world\n"
   827  					index := strings.Index(expected, "] ")
   828  					if index == -1 {
   829  						t.Fatalf("did not find ] separator: %s", expected)
   830  					}
   831  					expected = expected[0:index+2] + strconv.Quote(expected[index+2:]) + "\n"
   832  
   833  					// Warnings become info messages.
   834  					if strings.HasPrefix(expected, "W") {
   835  						expected = "I" + expected[1:]
   836  					}
   837  				}
   838  
   839  				if repl, ok := config.ExpectedOutputMapping[expected]; ok {
   840  					expected = repl
   841  				}
   842  				expectedWithPlaceholder := expected
   843  				expected = strings.ReplaceAll(expected, "<LINE>", fmt.Sprintf("%d", callLine))
   844  				if actual != expected {
   845  					if expectedWithPlaceholder == test.output {
   846  						t.Errorf("Output mismatch. Expected:\n%s\nActual:\n%s\n", expectedWithPlaceholder, actual)
   847  					} else {
   848  						t.Errorf("Output mismatch. klog:\n%s\nExpected:\n%s\nActual:\n%s\n", test.output, expectedWithPlaceholder, actual)
   849  					}
   850  				}
   851  			})
   852  		}
   853  	}
   854  }
   855  
   856  // Benchmark covers various special cases of emitting log output.
   857  // It can be used for arbitrary logr.Logger implementations.
   858  //
   859  // Loggers will be tested with direct calls to Info or
   860  // as backend for klog.
   861  func Benchmark(b *testing.B, config OutputConfig) {
   862  	for n, test := range tests {
   863  		b.Run(n, func(b *testing.B) {
   864  			state := klog.CaptureState()
   865  			defer state.Restore()
   866  			klog.SetOutput(io.Discard)
   867  			initPrintWithKlog(b, test)
   868  			b.ResetTimer()
   869  
   870  			if config.NewLogger == nil {
   871  				// Test klog.
   872  				for i := 0; i < b.N; i++ {
   873  					printWithKlog(test)
   874  				}
   875  				return
   876  			}
   877  
   878  			if config.AsBackend {
   879  				setLogger(config.NewLogger(io.Discard, 10, ""))
   880  				for i := 0; i < b.N; i++ {
   881  					printWithKlog(test)
   882  				}
   883  				return
   884  			}
   885  
   886  			if test.vmodule != "" && !config.SupportsVModule {
   887  				b.Skip("vmodule not supported")
   888  			}
   889  
   890  			logger := config.NewLogger(io.Discard, 10, test.vmodule)
   891  			b.ResetTimer()
   892  			for i := 0; i < b.N; i++ {
   893  				printWithLogger(logger, test)
   894  			}
   895  		})
   896  	}
   897  }
   898  
   899  func setLogger(logger logr.Logger) bool {
   900  	haveWriteKlogBuffer := false
   901  	var opts []klog.LoggerOption
   902  	if writer, ok := logger.GetSink().(textlogger.KlogBufferWriter); ok {
   903  		opts = append(opts, klog.WriteKlogBuffer(writer.WriteKlogBuffer))
   904  		haveWriteKlogBuffer = true
   905  	}
   906  	klog.SetLoggerWithOptions(logger, opts...)
   907  	return haveWriteKlogBuffer
   908  }
   909  
   910  func copySlice(in []interface{}) []interface{} {
   911  	return append([]interface{}{}, in...)
   912  }
   913  
   914  type kmeta struct {
   915  	Name, Namespace string
   916  }
   917  
   918  func (k kmeta) GetName() string {
   919  	return k.Name
   920  }
   921  
   922  func (k kmeta) GetNamespace() string {
   923  	return k.Namespace
   924  }
   925  
   926  var _ klog.KMetadata = kmeta{}
   927  
   928  type customErrorJSON struct {
   929  	s string
   930  }
   931  
   932  var _ error = &customErrorJSON{}
   933  var _ json.Marshaler = &customErrorJSON{}
   934  
   935  func (e *customErrorJSON) Error() string {
   936  	return e.s
   937  }
   938  
   939  func (e *customErrorJSON) MarshalJSON() ([]byte, error) {
   940  	return json.Marshal(strings.ToUpper(e.s))
   941  }
   942  
   943  type stringer struct {
   944  	s string
   945  }
   946  
   947  // String crashes when called for nil.
   948  func (s *stringer) String() string {
   949  	return s.s
   950  }
   951  
   952  var _ fmt.Stringer = &stringer{}
   953  
   954  type faultyStringer struct{}
   955  
   956  // String always panics.
   957  func (f faultyStringer) String() string {
   958  	panic("fake String panic")
   959  }
   960  
   961  var _ fmt.Stringer = faultyStringer{}
   962  
   963  type faultyMarshaler struct{}
   964  
   965  // MarshalLog always panics.
   966  func (f faultyMarshaler) MarshalLog() interface{} {
   967  	panic("fake MarshalLog panic")
   968  }
   969  
   970  var _ logr.Marshaler = faultyMarshaler{}
   971  
   972  type recursiveMarshaler struct{}
   973  
   974  // MarshalLog returns itself, which could cause the logger to recurse infinitely.
   975  func (r recursiveMarshaler) MarshalLog() interface{} {
   976  	return r
   977  }
   978  
   979  var _ logr.Marshaler = recursiveMarshaler{}
   980  
   981  type faultyError struct{}
   982  
   983  // Error always panics.
   984  func (f faultyError) Error() string {
   985  	panic("fake Error panic")
   986  }
   987  
   988  var _ error = faultyError{}
   989  
   990  // typeMeta implements fmt.Stringer and logr.Marshaler. config below
   991  // inherits those (incomplete!) implementations.
   992  type typeMeta struct {
   993  	Kind string
   994  }
   995  
   996  func (t typeMeta) String() string {
   997  	return "kind is " + t.Kind
   998  }
   999  
  1000  func (t typeMeta) MarshalLog() interface{} {
  1001  	return t.Kind
  1002  }
  1003  
  1004  type myConfig struct {
  1005  	typeMeta
  1006  
  1007  	RealField int
  1008  }
  1009  
  1010  var _ logr.Marshaler = myConfig{}
  1011  var _ fmt.Stringer = myConfig{}
  1012  
  1013  // This is a linked list. It can contain a cycle, which cannot be expressed in JSON.
  1014  type myList struct {
  1015  	Value int
  1016  	Next  *myList
  1017  }
  1018  
  1019  func newCyclicList() *myList {
  1020  	a := &myList{Value: 1}
  1021  	b := &myList{Value: 2, Next: a}
  1022  	a.Next = b
  1023  	return a
  1024  }
  1025  

View as plain text