Source file src/k8s.io/klog/v2/klog_test.go

Documentation: k8s.io/klog/v2

     1  // Go support for leveled logs, analogous to https://code.google.com/p/google-glog/
     2  //
     3  // Copyright 2013 Google Inc. All Rights Reserved.
     4  //
     5  // Licensed under the Apache License, Version 2.0 (the "License");
     6  // you may not use this file except in compliance with the License.
     7  // You may obtain a copy of the License at
     8  //
     9  //     http://www.apache.org/licenses/LICENSE-2.0
    10  //
    11  // Unless required by applicable law or agreed to in writing, software
    12  // distributed under the License is distributed on an "AS IS" BASIS,
    13  // WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
    14  // See the License for the specific language governing permissions and
    15  // limitations under the License.
    16  
    17  package klog
    18  
    19  import (
    20  	"bytes"
    21  	"errors"
    22  	"flag"
    23  	"fmt"
    24  	"io"
    25  	"io/ioutil"
    26  	stdLog "log"
    27  	"os"
    28  	"path/filepath"
    29  	"reflect"
    30  	"regexp"
    31  	"runtime"
    32  	"strconv"
    33  	"strings"
    34  	"sync"
    35  	"testing"
    36  	"time"
    37  
    38  	"github.com/go-logr/logr"
    39  
    40  	"k8s.io/klog/v2/internal/buffer"
    41  	testingclock "k8s.io/klog/v2/internal/clock/testing"
    42  	"k8s.io/klog/v2/internal/severity"
    43  	"k8s.io/klog/v2/internal/test"
    44  	"k8s.io/klog/v2/internal/test/require"
    45  )
    46  
    47  // TODO: This test package should be refactored so that tests cannot
    48  // interfere with each-other.
    49  
    50  // Test that shortHostname works as advertised.
    51  func TestShortHostname(t *testing.T) {
    52  	for hostname, expect := range map[string]string{
    53  		"":                "",
    54  		"host":            "host",
    55  		"host.google.com": "host",
    56  	} {
    57  		if got := shortHostname(hostname); expect != got {
    58  			t.Errorf("shortHostname(%q): expected %q, got %q", hostname, expect, got)
    59  		}
    60  	}
    61  }
    62  
    63  // flushBuffer wraps a bytes.Buffer to satisfy flushSyncWriter.
    64  type flushBuffer struct {
    65  	bytes.Buffer
    66  }
    67  
    68  func (f *flushBuffer) Flush() error {
    69  	return nil
    70  }
    71  
    72  func (f *flushBuffer) Sync() error {
    73  	return nil
    74  }
    75  
    76  // swap sets the log writers and returns the old array.
    77  func (l *loggingT) swap(writers [severity.NumSeverity]io.Writer) (old [severity.NumSeverity]io.Writer) {
    78  	l.mu.Lock()
    79  	defer l.mu.Unlock()
    80  	old = l.file
    81  	logging.file = writers
    82  	return
    83  }
    84  
    85  // newBuffers sets the log writers to all new byte buffers and returns the old array.
    86  func (l *loggingT) newBuffers() [severity.NumSeverity]io.Writer {
    87  	return l.swap([severity.NumSeverity]io.Writer{new(flushBuffer), new(flushBuffer), new(flushBuffer), new(flushBuffer)})
    88  }
    89  
    90  // contents returns the specified log value as a string.
    91  func contents(s severity.Severity) string {
    92  	return logging.file[s].(*flushBuffer).String()
    93  }
    94  
    95  // contains reports whether the string is contained in the log.
    96  func contains(s severity.Severity, str string) bool {
    97  	return strings.Contains(contents(s), str)
    98  }
    99  
   100  // setFlags configures the logging flags how the test expects them.
   101  func setFlags() {
   102  	logging.toStderr = false
   103  	logging.addDirHeader = false
   104  }
   105  
   106  // Test that Info works as advertised.
   107  func TestInfo(t *testing.T) {
   108  	defer CaptureState().Restore()
   109  	setFlags()
   110  	defer logging.swap(logging.newBuffers())
   111  	Info("test")
   112  	if !contains(severity.InfoLog, "I") {
   113  		t.Errorf("Info has wrong character: %q", contents(severity.InfoLog))
   114  	}
   115  	if !contains(severity.InfoLog, "test") {
   116  		t.Error("Info failed")
   117  	}
   118  }
   119  
   120  func TestInfoDepth(t *testing.T) {
   121  	defer CaptureState().Restore()
   122  	setFlags()
   123  	defer logging.swap(logging.newBuffers())
   124  
   125  	f := func() { InfoDepth(1, "depth-test1") }
   126  
   127  	// The next three lines must stay together
   128  	_, _, wantLine, _ := runtime.Caller(0)
   129  	InfoDepth(0, "depth-test0")
   130  	f()
   131  
   132  	msgs := strings.Split(strings.TrimSuffix(contents(severity.InfoLog), "\n"), "\n")
   133  	if len(msgs) != 2 {
   134  		t.Fatalf("Got %d lines, expected 2", len(msgs))
   135  	}
   136  
   137  	for i, m := range msgs {
   138  		if !strings.HasPrefix(m, "I") {
   139  			t.Errorf("InfoDepth[%d] has wrong character: %q", i, m)
   140  		}
   141  		w := fmt.Sprintf("depth-test%d", i)
   142  		if !strings.Contains(m, w) {
   143  			t.Errorf("InfoDepth[%d] missing %q: %q", i, w, m)
   144  		}
   145  
   146  		// pull out the line number (between : and ])
   147  		msg := m[strings.LastIndex(m, ":")+1:]
   148  		x := strings.Index(msg, "]")
   149  		if x < 0 {
   150  			t.Errorf("InfoDepth[%d]: missing ']': %q", i, m)
   151  			continue
   152  		}
   153  		line, err := strconv.Atoi(msg[:x])
   154  		if err != nil {
   155  			t.Errorf("InfoDepth[%d]: bad line number: %q", i, m)
   156  			continue
   157  		}
   158  		wantLine++
   159  		if wantLine != line {
   160  			t.Errorf("InfoDepth[%d]: got line %d, want %d", i, line, wantLine)
   161  		}
   162  	}
   163  }
   164  
   165  func init() {
   166  	CopyStandardLogTo("INFO")
   167  }
   168  
   169  // Test that CopyStandardLogTo panics on bad input.
   170  func TestCopyStandardLogToPanic(t *testing.T) {
   171  	defer func() {
   172  		if s, ok := recover().(string); !ok || !strings.Contains(s, "LOG") {
   173  			t.Errorf(`CopyStandardLogTo("LOG") should have panicked: %v`, s)
   174  		}
   175  	}()
   176  	CopyStandardLogTo("LOG")
   177  }
   178  
   179  // Test that using the standard log package logs to INFO.
   180  func TestStandardLog(t *testing.T) {
   181  	defer CaptureState().Restore()
   182  	setFlags()
   183  	defer logging.swap(logging.newBuffers())
   184  	stdLog.Print("test")
   185  	if !contains(severity.InfoLog, "I") {
   186  		t.Errorf("Info has wrong character: %q", contents(severity.InfoLog))
   187  	}
   188  	if !contains(severity.InfoLog, "test") {
   189  		t.Error("Info failed")
   190  	}
   191  }
   192  
   193  // Test that the header has the correct format.
   194  func TestHeader(t *testing.T) {
   195  	defer CaptureState().Restore()
   196  	setFlags()
   197  	defer logging.swap(logging.newBuffers())
   198  	defer func(previous func() time.Time) { timeNow = previous }(timeNow)
   199  	timeNow = func() time.Time {
   200  		return time.Date(2006, 1, 2, 15, 4, 5, .067890e9, time.Local)
   201  	}
   202  	buffer.Pid = 1234
   203  	Info("test")
   204  	var line int
   205  	format := "I0102 15:04:05.067890    1234 klog_test.go:%d] test\n"
   206  	n, err := fmt.Sscanf(contents(severity.InfoLog), format, &line)
   207  	if n != 1 || err != nil {
   208  		t.Errorf("log format error: %d elements, error %s:\n%s", n, err, contents(severity.InfoLog))
   209  	}
   210  	// Scanf treats multiple spaces as equivalent to a single space,
   211  	// so check for correct space-padding also.
   212  	want := fmt.Sprintf(format, line)
   213  	if contents(severity.InfoLog) != want {
   214  		t.Errorf("log format error: got:\n\t%q\nwant:\t%q", contents(severity.InfoLog), want)
   215  	}
   216  }
   217  
   218  func TestHeaderWithDir(t *testing.T) {
   219  	defer CaptureState().Restore()
   220  	setFlags()
   221  	logging.addDirHeader = true
   222  	defer logging.swap(logging.newBuffers())
   223  	defer func(previous func() time.Time) { timeNow = previous }(timeNow)
   224  	timeNow = func() time.Time {
   225  		return time.Date(2006, 1, 2, 15, 4, 5, .067890e9, time.Local)
   226  	}
   227  	pid = 1234
   228  	Info("test")
   229  	re := regexp.MustCompile(`I0102 15:04:05.067890    1234 (klog|v2)/klog_test.go:(\d+)] test\n`)
   230  	if !re.MatchString(contents(severity.InfoLog)) {
   231  		t.Errorf("log format error: line does not match regex:\n\t%q\n", contents(severity.InfoLog))
   232  	}
   233  }
   234  
   235  // Test that an Error log goes to Warning and Info.
   236  // Even in the Info log, the source character will be E, so the data should
   237  // all be identical.
   238  func TestError(t *testing.T) {
   239  	defer CaptureState().Restore()
   240  	setFlags()
   241  	defer logging.swap(logging.newBuffers())
   242  	Error("test")
   243  	if !contains(severity.ErrorLog, "E") {
   244  		t.Errorf("Error has wrong character: %q", contents(severity.ErrorLog))
   245  	}
   246  	if !contains(severity.ErrorLog, "test") {
   247  		t.Error("Error failed")
   248  	}
   249  	str := contents(severity.ErrorLog)
   250  	if !contains(severity.WarningLog, str) {
   251  		t.Error("Warning failed")
   252  	}
   253  	if !contains(severity.InfoLog, str) {
   254  		t.Error("Info failed")
   255  	}
   256  }
   257  
   258  // Test that an Error log does not goes to Warning and Info.
   259  // Even in the Info log, the source character will be E, so the data should
   260  // all be identical.
   261  func TestErrorWithOneOutput(t *testing.T) {
   262  	defer CaptureState().Restore()
   263  	setFlags()
   264  	logging.oneOutput = true
   265  	defer logging.swap(logging.newBuffers())
   266  	Error("test")
   267  	if !contains(severity.ErrorLog, "E") {
   268  		t.Errorf("Error has wrong character: %q", contents(severity.ErrorLog))
   269  	}
   270  	if !contains(severity.ErrorLog, "test") {
   271  		t.Error("Error failed")
   272  	}
   273  	str := contents(severity.ErrorLog)
   274  	if contains(severity.WarningLog, str) {
   275  		t.Error("Warning failed")
   276  	}
   277  	if contains(severity.InfoLog, str) {
   278  		t.Error("Info failed")
   279  	}
   280  }
   281  
   282  // Test that a Warning log goes to Info.
   283  // Even in the Info log, the source character will be W, so the data should
   284  // all be identical.
   285  func TestWarning(t *testing.T) {
   286  	defer CaptureState().Restore()
   287  	setFlags()
   288  	defer logging.swap(logging.newBuffers())
   289  	Warning("test")
   290  	if !contains(severity.WarningLog, "W") {
   291  		t.Errorf("Warning has wrong character: %q", contents(severity.WarningLog))
   292  	}
   293  	if !contains(severity.WarningLog, "test") {
   294  		t.Error("Warning failed")
   295  	}
   296  	str := contents(severity.WarningLog)
   297  	if !contains(severity.InfoLog, str) {
   298  		t.Error("Info failed")
   299  	}
   300  }
   301  
   302  // Test that a Warning log does not goes to Info.
   303  // Even in the Info log, the source character will be W, so the data should
   304  // all be identical.
   305  func TestWarningWithOneOutput(t *testing.T) {
   306  	defer CaptureState().Restore()
   307  	setFlags()
   308  	logging.oneOutput = true
   309  	defer logging.swap(logging.newBuffers())
   310  	Warning("test")
   311  	if !contains(severity.WarningLog, "W") {
   312  		t.Errorf("Warning has wrong character: %q", contents(severity.WarningLog))
   313  	}
   314  	if !contains(severity.WarningLog, "test") {
   315  		t.Error("Warning failed")
   316  	}
   317  	str := contents(severity.WarningLog)
   318  	if contains(severity.InfoLog, str) {
   319  		t.Error("Info failed")
   320  	}
   321  }
   322  
   323  // Test that a V log goes to Info.
   324  func TestV(t *testing.T) {
   325  	defer CaptureState().Restore()
   326  	setFlags()
   327  	defer logging.swap(logging.newBuffers())
   328  	require.NoError(t, logging.verbosity.Set("2"))
   329  	V(2).Info("test")
   330  	if !contains(severity.InfoLog, "I") {
   331  		t.Errorf("Info has wrong character: %q", contents(severity.InfoLog))
   332  	}
   333  	if !contains(severity.InfoLog, "test") {
   334  		t.Error("Info failed")
   335  	}
   336  }
   337  
   338  // Test that a vmodule enables a log in this file.
   339  func TestVmoduleOn(t *testing.T) {
   340  	defer CaptureState().Restore()
   341  	setFlags()
   342  	defer logging.swap(logging.newBuffers())
   343  	require.NoError(t, logging.vmodule.Set("klog_test=2"))
   344  	if !V(1).Enabled() {
   345  		t.Error("V not enabled for 1")
   346  	}
   347  	if !V(2).Enabled() {
   348  		t.Error("V not enabled for 2")
   349  	}
   350  	if V(3).Enabled() {
   351  		t.Error("V enabled for 3")
   352  	}
   353  	V(2).Info("test")
   354  	if !contains(severity.InfoLog, "I") {
   355  		t.Errorf("Info has wrong character: %q", contents(severity.InfoLog))
   356  	}
   357  	if !contains(severity.InfoLog, "test") {
   358  		t.Error("Info failed")
   359  	}
   360  }
   361  
   362  // Test that a vmodule of another file does not enable a log in this file.
   363  func TestVmoduleOff(t *testing.T) {
   364  	defer CaptureState().Restore()
   365  	setFlags()
   366  	defer logging.swap(logging.newBuffers())
   367  	require.NoError(t, logging.vmodule.Set("notthisfile=2"))
   368  	for i := 1; i <= 3; i++ {
   369  		if V(Level(i)).Enabled() {
   370  			t.Errorf("V enabled for %d", i)
   371  		}
   372  	}
   373  	V(2).Info("test")
   374  	if contents(severity.InfoLog) != "" {
   375  		t.Error("V logged incorrectly")
   376  	}
   377  }
   378  
   379  func TestSetOutputDataRace(*testing.T) {
   380  	defer CaptureState().Restore()
   381  	setFlags()
   382  	defer logging.swap(logging.newBuffers())
   383  	var wg sync.WaitGroup
   384  	var daemons []*flushDaemon
   385  	for i := 1; i <= 50; i++ {
   386  		daemon := newFlushDaemon(logging.lockAndFlushAll, nil)
   387  		daemon.run(time.Second)
   388  		daemons = append(daemons, daemon)
   389  	}
   390  	for i := 1; i <= 50; i++ {
   391  		wg.Add(1)
   392  		go func() {
   393  			defer wg.Done()
   394  			SetOutput(ioutil.Discard)
   395  		}()
   396  	}
   397  	for i := 1; i <= 50; i++ {
   398  		daemon := newFlushDaemon(logging.lockAndFlushAll, nil)
   399  		daemon.run(time.Second)
   400  		daemons = append(daemons, daemon)
   401  	}
   402  	for i := 1; i <= 50; i++ {
   403  		wg.Add(1)
   404  		go func() {
   405  			defer wg.Done()
   406  			SetOutputBySeverity("INFO", ioutil.Discard)
   407  		}()
   408  	}
   409  	for i := 1; i <= 50; i++ {
   410  		daemon := newFlushDaemon(logging.lockAndFlushAll, nil)
   411  		daemon.run(time.Second)
   412  		daemons = append(daemons, daemon)
   413  	}
   414  	wg.Wait()
   415  	for _, d := range daemons {
   416  		d.stop()
   417  	}
   418  }
   419  
   420  func TestLogToOutput(t *testing.T) {
   421  	defer CaptureState().Restore()
   422  	logging.toStderr = true
   423  	defer logging.swap(logging.newBuffers())
   424  	buf := new(bytes.Buffer)
   425  	SetOutput(buf)
   426  	LogToStderr(false)
   427  
   428  	Info("Does logging to an output work?")
   429  
   430  	str := buf.String()
   431  	if !strings.Contains(str, "Does logging to an output work?") {
   432  		t.Fatalf("Expected %q to contain \"Does logging to an output work?\"", str)
   433  	}
   434  }
   435  
   436  // vGlobs are patterns that match/don't match this file at V=2.
   437  var vGlobs = map[string]bool{
   438  	// Easy to test the numeric match here.
   439  	"klog_test=1": false, // If -vmodule sets V to 1, V(2) will fail.
   440  	"klog_test=2": true,
   441  	"klog_test=3": true, // If -vmodule sets V to 1, V(3) will succeed.
   442  	// These all use 2 and check the patterns. All are true.
   443  	"*=2":           true,
   444  	"?l*=2":         true,
   445  	"????_*=2":      true,
   446  	"??[mno]?_*t=2": true,
   447  	// These all use 2 and check the patterns. All are false.
   448  	"*x=2":         false,
   449  	"m*=2":         false,
   450  	"??_*=2":       false,
   451  	"?[abc]?_*t=2": false,
   452  }
   453  
   454  // Test that vmodule globbing works as advertised.
   455  func testVmoduleGlob(pat string, match bool, t *testing.T) {
   456  	defer CaptureState().Restore()
   457  	setFlags()
   458  	defer logging.swap(logging.newBuffers())
   459  	require.NoError(t, logging.vmodule.Set(pat))
   460  	if V(2).Enabled() != match {
   461  		t.Errorf("incorrect match for %q: got %#v expected %#v", pat, V(2), match)
   462  	}
   463  }
   464  
   465  // Test that a vmodule globbing works as advertised.
   466  func TestVmoduleGlob(t *testing.T) {
   467  	for glob, match := range vGlobs {
   468  		testVmoduleGlob(glob, match, t)
   469  	}
   470  }
   471  
   472  func TestRollover(t *testing.T) {
   473  	defer CaptureState().Restore()
   474  	setFlags()
   475  	var err error
   476  	defer func(previous func(error)) { logExitFunc = previous }(logExitFunc)
   477  	logExitFunc = func(e error) {
   478  		err = e
   479  	}
   480  	MaxSize = 512
   481  	Info("x") // Be sure we have a file.
   482  	info, ok := logging.file[severity.InfoLog].(*syncBuffer)
   483  	if !ok {
   484  		t.Fatal("info wasn't created")
   485  	}
   486  	if err != nil {
   487  		t.Fatalf("info has initial error: %v", err)
   488  	}
   489  	fname0 := info.file.Name()
   490  	Info(strings.Repeat("x", int(MaxSize))) // force a rollover
   491  	if err != nil {
   492  		t.Fatalf("info has error after big write: %v", err)
   493  	}
   494  
   495  	// Make sure the next log file gets a file name with a different
   496  	// time stamp.
   497  	//
   498  	// TODO: determine whether we need to support subsecond log
   499  	// rotation.  C++ does not appear to handle this case (nor does it
   500  	// handle Daylight Savings Time properly).
   501  	time.Sleep(1 * time.Second)
   502  
   503  	Info("x") // create a new file
   504  	if err != nil {
   505  		t.Fatalf("error after rotation: %v", err)
   506  	}
   507  	fname1 := info.file.Name()
   508  	if fname0 == fname1 {
   509  		t.Errorf("info.f.Name did not change: %v", fname0)
   510  	}
   511  	if info.nbytes >= info.maxbytes {
   512  		t.Errorf("file size was not reset: %d", info.nbytes)
   513  	}
   514  }
   515  
   516  func TestOpenAppendOnStart(t *testing.T) {
   517  	const (
   518  		x string = "xxxxxxxxxx"
   519  		y string = "yyyyyyyyyy"
   520  	)
   521  
   522  	defer CaptureState().Restore()
   523  	setFlags()
   524  	var err error
   525  	defer func(previous func(error)) { logExitFunc = previous }(logExitFunc)
   526  	logExitFunc = func(e error) {
   527  		err = e
   528  	}
   529  
   530  	f, err := ioutil.TempFile("", "test_klog_OpenAppendOnStart")
   531  	if err != nil {
   532  		t.Fatalf("unexpected error: %v", err)
   533  	}
   534  	defer os.Remove(f.Name())
   535  	logging.logFile = f.Name()
   536  
   537  	// Erase files created by prior tests,
   538  	for i := range logging.file {
   539  		logging.file[i] = nil
   540  	}
   541  
   542  	// Logging creates the file
   543  	Info(x)
   544  	sb, ok := logging.file[severity.InfoLog].(*syncBuffer)
   545  	if !ok {
   546  		t.Fatal("info wasn't created")
   547  	}
   548  
   549  	// ensure we wrote what we expected
   550  	needToSync := logging.flushAll()
   551  	if needToSync.num != 1 || needToSync.files[0] != sb.file {
   552  		t.Errorf("Should have received exactly the file from severity.InfoLog for syncing, got instead: %+v", needToSync)
   553  	}
   554  	logging.syncAll(needToSync)
   555  	b, err := ioutil.ReadFile(logging.logFile)
   556  	if err != nil {
   557  		t.Fatalf("unexpected error: %v", err)
   558  	}
   559  	if !strings.Contains(string(b), x) {
   560  		t.Fatalf("got %s, missing expected Info log: %s", string(b), x)
   561  	}
   562  
   563  	// Set the file to nil so it gets "created" (opened) again on the next write.
   564  	for i := range logging.file {
   565  		logging.file[i] = nil
   566  	}
   567  
   568  	// Logging again should open the file again with O_APPEND instead of O_TRUNC
   569  	Info(y)
   570  	// ensure we wrote what we expected
   571  	logging.lockAndFlushAll()
   572  	b, err = ioutil.ReadFile(logging.logFile)
   573  	if err != nil {
   574  		t.Fatalf("unexpected error: %v", err)
   575  	}
   576  	if !strings.Contains(string(b), y) {
   577  		t.Fatalf("got %s, missing expected Info log: %s", string(b), y)
   578  	}
   579  	// The initial log message should be preserved across create calls.
   580  	logging.lockAndFlushAll()
   581  	b, err = ioutil.ReadFile(logging.logFile)
   582  	if err != nil {
   583  		t.Fatalf("unexpected error: %v", err)
   584  	}
   585  	if !strings.Contains(string(b), x) {
   586  		t.Fatalf("got %s, missing expected Info log: %s", string(b), x)
   587  	}
   588  }
   589  
   590  func TestLogBacktraceAt(t *testing.T) {
   591  	defer CaptureState().Restore()
   592  	setFlags()
   593  	defer logging.swap(logging.newBuffers())
   594  	// The peculiar style of this code simplifies line counting and maintenance of the
   595  	// tracing block below.
   596  	var infoLine string
   597  	setTraceLocation := func(file string, line int, ok bool, delta int) {
   598  		if !ok {
   599  			t.Fatal("could not get file:line")
   600  		}
   601  		_, file = filepath.Split(file)
   602  		infoLine = fmt.Sprintf("%s:%d", file, line+delta)
   603  		err := logging.traceLocation.Set(infoLine)
   604  		if err != nil {
   605  			t.Fatal("error setting log_backtrace_at: ", err)
   606  		}
   607  	}
   608  	{
   609  		// Start of tracing block. These lines know about each other's relative position.
   610  		_, file, line, ok := runtime.Caller(0)
   611  		setTraceLocation(file, line, ok, +2) // Two lines between Caller and Info calls.
   612  		Info("we want a stack trace here")
   613  	}
   614  	numAppearances := strings.Count(contents(severity.InfoLog), infoLine)
   615  	if numAppearances < 2 {
   616  		// Need 2 appearances, one in the log header and one in the trace:
   617  		//   log_test.go:281: I0511 16:36:06.952398 02238 log_test.go:280] we want a stack trace here
   618  		//   ...
   619  		//   k8s.io/klog/klog_test.go:280 (0x41ba91)
   620  		//   ...
   621  		// We could be more precise but that would require knowing the details
   622  		// of the traceback format, which may not be dependable.
   623  		t.Fatal("got no trace back; log is ", contents(severity.InfoLog))
   624  	}
   625  }
   626  
   627  func BenchmarkHeader(b *testing.B) {
   628  	for i := 0; i < b.N; i++ {
   629  		buf, _, _ := logging.header(severity.InfoLog, 0)
   630  		buffer.PutBuffer(buf)
   631  	}
   632  }
   633  
   634  func BenchmarkHeaderWithDir(b *testing.B) {
   635  	logging.addDirHeader = true
   636  	for i := 0; i < b.N; i++ {
   637  		buf, _, _ := logging.header(severity.InfoLog, 0)
   638  		buffer.PutBuffer(buf)
   639  	}
   640  }
   641  
   642  // Ensure that benchmarks have side effects to avoid compiler optimization
   643  var result interface{}
   644  var enabled bool
   645  
   646  func BenchmarkV(b *testing.B) {
   647  	var v Verbose
   648  	for i := 0; i < b.N; i++ {
   649  		v = V(10)
   650  	}
   651  	enabled = v.Enabled()
   652  }
   653  
   654  func BenchmarkKRef(b *testing.B) {
   655  	var r ObjectRef
   656  	for i := 0; i < b.N; i++ {
   657  		r = KRef("namespace", "name")
   658  	}
   659  	result = r
   660  }
   661  
   662  func BenchmarkKObj(b *testing.B) {
   663  	a := test.KMetadataMock{Name: "a", NS: "a"}
   664  	var r ObjectRef
   665  	for i := 0; i < b.N; i++ {
   666  		r = KObj(&a)
   667  	}
   668  	result = r
   669  }
   670  
   671  // BenchmarkKObjs measures the (pretty typical) case
   672  // where KObjs is used in a V(5).InfoS call that never
   673  // emits a log entry because verbosity is lower than 5.
   674  // For performance when the result of KObjs gets formatted,
   675  // see examples/benchmarks.
   676  //
   677  // This uses two different patterns:
   678  // - directly calling klog.V(5).Info
   679  // - guarding the call with Enabled
   680  func BenchmarkKObjs(b *testing.B) {
   681  	for length := 0; length <= 100; length += 10 {
   682  		b.Run(fmt.Sprintf("%d", length), func(b *testing.B) {
   683  			arg := make([]interface{}, length)
   684  			for i := 0; i < length; i++ {
   685  				arg[i] = test.KMetadataMock{Name: "a", NS: "a"}
   686  			}
   687  
   688  			b.Run("simple", func(b *testing.B) {
   689  				b.ResetTimer()
   690  				for i := 0; i < b.N; i++ {
   691  					V(5).InfoS("benchmark", "objs", KObjs(arg))
   692  				}
   693  			})
   694  
   695  			b.Run("conditional", func(b *testing.B) {
   696  				b.ResetTimer()
   697  				for i := 0; i < b.N; i++ {
   698  					if klogV := V(5); klogV.Enabled() {
   699  						klogV.InfoS("benchmark", "objs", KObjs(arg))
   700  					}
   701  				}
   702  			})
   703  		})
   704  	}
   705  }
   706  
   707  // BenchmarkKObjSlice corresponds to BenchmarkKObjs except that it uses KObjSlice
   708  func BenchmarkKObjSlice(b *testing.B) {
   709  	for length := 0; length <= 100; length += 10 {
   710  		b.Run(fmt.Sprintf("%d", length), func(b *testing.B) {
   711  			arg := make([]interface{}, length)
   712  			for i := 0; i < length; i++ {
   713  				arg[i] = test.KMetadataMock{Name: "a", NS: "a"}
   714  			}
   715  
   716  			b.Run("simple", func(b *testing.B) {
   717  				b.ResetTimer()
   718  				for i := 0; i < b.N; i++ {
   719  					V(5).InfoS("benchmark", "objs", KObjSlice(arg))
   720  				}
   721  			})
   722  
   723  			b.Run("conditional", func(b *testing.B) {
   724  				b.ResetTimer()
   725  				for i := 0; i < b.N; i++ {
   726  					if klogV := V(5); klogV.Enabled() {
   727  						klogV.InfoS("benchmark", "objs", KObjSlice(arg))
   728  					}
   729  				}
   730  			})
   731  		})
   732  	}
   733  }
   734  
   735  // BenchmarkScalars corresponds to BenchmarkKObjs except that it avoids function
   736  // calls for the parameters.
   737  func BenchmarkScalars(b *testing.B) {
   738  	b.Run("simple", func(b *testing.B) {
   739  		b.ResetTimer()
   740  		for i := 0; i < b.N; i++ {
   741  			V(5).InfoS("benchmark", "str", "hello world", "int", 42)
   742  		}
   743  	})
   744  
   745  	b.Run("conditional", func(b *testing.B) {
   746  		b.ResetTimer()
   747  		for i := 0; i < b.N; i++ {
   748  			if klogV := V(5); klogV.Enabled() {
   749  				klogV.InfoS("benchmark", "str", "hello world", "int", 42)
   750  			}
   751  		}
   752  	})
   753  }
   754  
   755  // BenchmarkScalarsWithLogger is the same as BenchmarkScalars except that it uses
   756  // a go-logr instance.
   757  func BenchmarkScalarsWithLogger(b *testing.B) {
   758  	logger := Background()
   759  	b.Run("simple", func(b *testing.B) {
   760  		b.ResetTimer()
   761  		for i := 0; i < b.N; i++ {
   762  			logger.V(5).Info("benchmark", "str", "hello world", "int", 42)
   763  		}
   764  	})
   765  
   766  	b.Run("conditional", func(b *testing.B) {
   767  		b.ResetTimer()
   768  		for i := 0; i < b.N; i++ {
   769  			if loggerV := logger.V(5); loggerV.Enabled() {
   770  				loggerV.Info("benchmark", "str", "hello world", "int", 42)
   771  			}
   772  		}
   773  	})
   774  }
   775  
   776  // BenchmarKObjSliceWithLogger is the same as BenchmarkKObjSlice except that it
   777  // uses a go-logr instance and a slice with a single entry. BenchmarkKObjSlice
   778  // shows that the overhead for KObjSlice is constant and doesn't depend on the
   779  // slice length when logging is off.
   780  func BenchmarkKObjSliceWithLogger(b *testing.B) {
   781  	logger := Background()
   782  	arg := []interface{}{test.KMetadataMock{Name: "a", NS: "a"}}
   783  	b.Run("simple", func(b *testing.B) {
   784  		b.ResetTimer()
   785  		for i := 0; i < b.N; i++ {
   786  			logger.V(5).Info("benchmark", "objs", KObjSlice(arg))
   787  		}
   788  	})
   789  
   790  	b.Run("conditional", func(b *testing.B) {
   791  		b.ResetTimer()
   792  		for i := 0; i < b.N; i++ {
   793  			if loggerV := logger.V(5); loggerV.Enabled() {
   794  				loggerV.Info("benchmark", "objs", KObjSlice(arg))
   795  			}
   796  		}
   797  	})
   798  }
   799  
   800  func BenchmarkLogs(b *testing.B) {
   801  	defer CaptureState().Restore()
   802  	setFlags()
   803  	defer logging.swap(logging.newBuffers())
   804  
   805  	testFile, err := ioutil.TempFile("", "test.log")
   806  	if err != nil {
   807  		b.Fatal("unable to create temporary file")
   808  	}
   809  	defer os.Remove(testFile.Name())
   810  
   811  	require.NoError(b, logging.verbosity.Set("0"))
   812  	logging.toStderr = false
   813  	logging.alsoToStderr = false
   814  	logging.stderrThreshold = severityValue{
   815  		Severity: severity.FatalLog,
   816  	}
   817  	logging.logFile = testFile.Name()
   818  	logging.swap([severity.NumSeverity]io.Writer{nil, nil, nil, nil})
   819  
   820  	for i := 0; i < b.N; i++ {
   821  		Error("error")
   822  		Warning("warning")
   823  		Info("info")
   824  	}
   825  	needToSync := logging.flushAll()
   826  	sb, ok := logging.file[severity.InfoLog].(*syncBuffer)
   827  	if !ok {
   828  		b.Fatal("info wasn't created")
   829  	}
   830  	if needToSync.num != 1 || needToSync.files[0] != sb.file {
   831  		b.Fatalf("Should have received exactly the file from severity.InfoLog for syncing, got instead: %+v", needToSync)
   832  	}
   833  	logging.syncAll(needToSync)
   834  }
   835  
   836  func BenchmarkFlush(b *testing.B) {
   837  	defer CaptureState().Restore()
   838  	setFlags()
   839  	defer logging.swap(logging.newBuffers())
   840  
   841  	testFile, err := ioutil.TempFile("", "test.log")
   842  	if err != nil {
   843  		b.Fatal("unable to create temporary file")
   844  	}
   845  	defer os.Remove(testFile.Name())
   846  
   847  	require.NoError(b, logging.verbosity.Set("0"))
   848  	logging.toStderr = false
   849  	logging.alsoToStderr = false
   850  	logging.stderrThreshold = severityValue{
   851  		Severity: severity.FatalLog,
   852  	}
   853  	logging.logFile = testFile.Name()
   854  	logging.swap([severity.NumSeverity]io.Writer{nil, nil, nil, nil})
   855  
   856  	// Create output file.
   857  	Info("info")
   858  	needToSync := logging.flushAll()
   859  
   860  	if needToSync.num != 1 {
   861  		b.Fatalf("expected exactly one file to sync, got: %+v", needToSync)
   862  	}
   863  
   864  	b.ResetTimer()
   865  
   866  	for i := 0; i < b.N; i++ {
   867  		needToSync := logging.flushAll()
   868  		logging.syncAll(needToSync)
   869  	}
   870  }
   871  
   872  // Test the logic on checking log size limitation.
   873  func TestFileSizeCheck(t *testing.T) {
   874  	defer CaptureState().Restore()
   875  	setFlags()
   876  	testData := map[string]struct {
   877  		testLogFile          string
   878  		testLogFileMaxSizeMB uint64
   879  		testCurrentSize      uint64
   880  		expectedResult       bool
   881  	}{
   882  		"logFile not specified, exceeds max size": {
   883  			testLogFile:          "",
   884  			testLogFileMaxSizeMB: 1,
   885  			testCurrentSize:      1024 * 1024 * 2000, //exceeds the maxSize
   886  			expectedResult:       true,
   887  		},
   888  
   889  		"logFile not specified, not exceeds max size": {
   890  			testLogFile:          "",
   891  			testLogFileMaxSizeMB: 1,
   892  			testCurrentSize:      1024 * 1024 * 1000, //smaller than the maxSize
   893  			expectedResult:       false,
   894  		},
   895  		"logFile specified, exceeds max size": {
   896  			testLogFile:          "/tmp/test.log",
   897  			testLogFileMaxSizeMB: 500,                // 500MB
   898  			testCurrentSize:      1024 * 1024 * 1000, //exceeds the logFileMaxSizeMB
   899  			expectedResult:       true,
   900  		},
   901  		"logFile specified, not exceeds max size": {
   902  			testLogFile:          "/tmp/test.log",
   903  			testLogFileMaxSizeMB: 500,               // 500MB
   904  			testCurrentSize:      1024 * 1024 * 300, //smaller than the logFileMaxSizeMB
   905  			expectedResult:       false,
   906  		},
   907  	}
   908  
   909  	for name, test := range testData {
   910  		logging.logFile = test.testLogFile
   911  		logging.logFileMaxSizeMB = test.testLogFileMaxSizeMB
   912  		actualResult := test.testCurrentSize >= CalculateMaxSize()
   913  		if test.expectedResult != actualResult {
   914  			t.Fatalf("Error on test case '%v': Was expecting result equals %v, got %v",
   915  				name, test.expectedResult, actualResult)
   916  		}
   917  	}
   918  }
   919  
   920  func TestInitFlags(t *testing.T) {
   921  	defer CaptureState().Restore()
   922  	setFlags()
   923  
   924  	fs1 := flag.NewFlagSet("test1", flag.PanicOnError)
   925  	InitFlags(fs1)
   926  	require.NoError(t, fs1.Set("log_dir", "/test1"))
   927  	require.NoError(t, fs1.Set("log_file_max_size", "1"))
   928  	fs2 := flag.NewFlagSet("test2", flag.PanicOnError)
   929  	InitFlags(fs2)
   930  	if logging.logDir != "/test1" {
   931  		t.Fatalf("Expected log_dir to be %q, got %q", "/test1", logging.logDir)
   932  	}
   933  	require.NoError(t, fs2.Set("log_file_max_size", "2048"))
   934  	if logging.logFileMaxSizeMB != 2048 {
   935  		t.Fatal("Expected log_file_max_size to be 2048")
   936  	}
   937  }
   938  
   939  func TestCommandLine(t *testing.T) {
   940  	var fs flag.FlagSet
   941  	InitFlags(&fs)
   942  
   943  	expectedFlags := `  -add_dir_header
   944      	If true, adds the file directory to the header of the log messages
   945    -alsologtostderr
   946      	log to standard error as well as files (no effect when -logtostderr=true)
   947    -log_backtrace_at value
   948      	when logging hits line file:N, emit a stack trace
   949    -log_dir string
   950      	If non-empty, write log files in this directory (no effect when -logtostderr=true)
   951    -log_file string
   952      	If non-empty, use this log file (no effect when -logtostderr=true)
   953    -log_file_max_size uint
   954      	Defines the maximum size a log file can grow to (no effect when -logtostderr=true). Unit is megabytes. If the value is 0, the maximum file size is unlimited. (default 1800)
   955    -logtostderr
   956      	log to standard error instead of files (default true)
   957    -one_output
   958      	If true, only write logs to their native severity level (vs also writing to each lower severity level; no effect when -logtostderr=true)
   959    -skip_headers
   960      	If true, avoid header prefixes in the log messages
   961    -skip_log_headers
   962      	If true, avoid headers when opening log files (no effect when -logtostderr=true)
   963    -stderrthreshold value
   964      	logs at or above this threshold go to stderr when writing to files and stderr (no effect when -logtostderr=true or -alsologtostderr=true) (default 2)
   965    -v value
   966      	number for the log level verbosity
   967    -vmodule value
   968      	comma-separated list of pattern=N settings for file-filtered logging
   969  `
   970  
   971  	var output bytes.Buffer
   972  	fs.SetOutput(&output)
   973  	fs.PrintDefaults()
   974  	actualFlags := output.String()
   975  
   976  	if expectedFlags != actualFlags {
   977  		t.Fatalf("Command line changed.\nExpected:\n%q\nActual:\n%q\n", expectedFlags, actualFlags)
   978  	}
   979  }
   980  
   981  func TestInfoObjectRef(t *testing.T) {
   982  	defer CaptureState().Restore()
   983  	setFlags()
   984  	defer logging.swap(logging.newBuffers())
   985  
   986  	tests := []struct {
   987  		name string
   988  		ref  ObjectRef
   989  		want string
   990  	}{
   991  		{
   992  			name: "with ns",
   993  			ref: ObjectRef{
   994  				Name:      "test-name",
   995  				Namespace: "test-ns",
   996  			},
   997  			want: "test-ns/test-name",
   998  		},
   999  		{
  1000  			name: "without ns",
  1001  			ref: ObjectRef{
  1002  				Name:      "test-name",
  1003  				Namespace: "",
  1004  			},
  1005  			want: "test-name",
  1006  		},
  1007  		{
  1008  			name: "empty",
  1009  			ref:  ObjectRef{},
  1010  			want: "",
  1011  		},
  1012  	}
  1013  
  1014  	for _, tt := range tests {
  1015  		t.Run(tt.name, func(t *testing.T) {
  1016  			Info(tt.ref)
  1017  			if !contains(severity.InfoLog, tt.want) {
  1018  				t.Errorf("expected %v, got %v", tt.want, contents(severity.InfoLog))
  1019  			}
  1020  		})
  1021  	}
  1022  }
  1023  
  1024  func TestKObj(t *testing.T) {
  1025  	tests := []struct {
  1026  		name string
  1027  		obj  KMetadata
  1028  		want ObjectRef
  1029  	}{
  1030  		{
  1031  			name: "nil passed as pointer KMetadata implementation",
  1032  			obj:  (*test.PtrKMetadataMock)(nil),
  1033  			want: ObjectRef{},
  1034  		},
  1035  		{
  1036  			name: "empty struct passed as non-pointer KMetadata implementation",
  1037  			obj:  test.KMetadataMock{},
  1038  			want: ObjectRef{},
  1039  		},
  1040  		{
  1041  			name: "nil pointer passed to non-pointer KMetadata implementation",
  1042  			obj:  (*test.KMetadataMock)(nil),
  1043  			want: ObjectRef{},
  1044  		},
  1045  		{
  1046  			name: "nil",
  1047  			obj:  nil,
  1048  			want: ObjectRef{},
  1049  		},
  1050  		{
  1051  			name: "with ns",
  1052  			obj:  &test.KMetadataMock{Name: "test-name", NS: "test-ns"},
  1053  			want: ObjectRef{
  1054  				Name:      "test-name",
  1055  				Namespace: "test-ns",
  1056  			},
  1057  		},
  1058  		{
  1059  			name: "without ns",
  1060  			obj:  &test.KMetadataMock{Name: "test-name", NS: ""},
  1061  			want: ObjectRef{
  1062  				Name: "test-name",
  1063  			},
  1064  		},
  1065  	}
  1066  
  1067  	for _, tt := range tests {
  1068  		t.Run(tt.name, func(t *testing.T) {
  1069  			if KObj(tt.obj) != tt.want {
  1070  				t.Errorf("expected %v, got %v", tt.want, KObj(tt.obj))
  1071  			}
  1072  		})
  1073  	}
  1074  }
  1075  
  1076  func TestKRef(t *testing.T) {
  1077  	tests := []struct {
  1078  		testname  string
  1079  		name      string
  1080  		namespace string
  1081  		want      ObjectRef
  1082  	}{
  1083  		{
  1084  			testname:  "with ns",
  1085  			name:      "test-name",
  1086  			namespace: "test-ns",
  1087  			want: ObjectRef{
  1088  				Name:      "test-name",
  1089  				Namespace: "test-ns",
  1090  			},
  1091  		},
  1092  		{
  1093  			testname: "without ns",
  1094  			name:     "test-name",
  1095  			want: ObjectRef{
  1096  				Name: "test-name",
  1097  			},
  1098  		},
  1099  	}
  1100  
  1101  	for _, tt := range tests {
  1102  		t.Run(tt.testname, func(t *testing.T) {
  1103  			if KRef(tt.namespace, tt.name) != tt.want {
  1104  				t.Errorf("expected %v, got %v", tt.want, KRef(tt.namespace, tt.name))
  1105  			}
  1106  		})
  1107  	}
  1108  }
  1109  
  1110  // Test that InfoS and InfoSDepth work as advertised.
  1111  func TestInfoS(t *testing.T) {
  1112  	defer CaptureState().Restore()
  1113  	setFlags()
  1114  	defer logging.swap(logging.newBuffers())
  1115  	timeNow = func() time.Time {
  1116  		return time.Date(2006, 1, 2, 15, 4, 5, .067890e9, time.Local)
  1117  	}
  1118  	pid = 1234
  1119  	var testDataInfo = []struct {
  1120  		msg        string
  1121  		format     string
  1122  		keysValues []interface{}
  1123  	}{
  1124  		{
  1125  			msg:        "test",
  1126  			format:     "I0102 15:04:05.067890    1234 klog_test.go:%d] \"test\" pod=\"kubedns\"\n",
  1127  			keysValues: []interface{}{"pod", "kubedns"},
  1128  		},
  1129  		{
  1130  			msg:        "test",
  1131  			format:     "I0102 15:04:05.067890    1234 klog_test.go:%d] \"test\" replicaNum=20\n",
  1132  			keysValues: []interface{}{"replicaNum", 20},
  1133  		},
  1134  		{
  1135  			msg:        "test",
  1136  			format:     "I0102 15:04:05.067890    1234 klog_test.go:%d] \"test\" err=\"test error\"\n",
  1137  			keysValues: []interface{}{"err", errors.New("test error")},
  1138  		},
  1139  		{
  1140  			msg:        "test",
  1141  			format:     "I0102 15:04:05.067890    1234 klog_test.go:%d] \"test\" err=\"test error\"\n",
  1142  			keysValues: []interface{}{"err", errors.New("test error")},
  1143  		},
  1144  	}
  1145  
  1146  	functions := []func(msg string, keyAndValues ...interface{}){
  1147  		InfoS,
  1148  		myInfoS,
  1149  	}
  1150  	for _, f := range functions {
  1151  		for _, data := range testDataInfo {
  1152  			logging.file[severity.InfoLog] = &flushBuffer{}
  1153  			f(data.msg, data.keysValues...)
  1154  			var line int
  1155  			n, err := fmt.Sscanf(contents(severity.InfoLog), data.format, &line)
  1156  			if n != 1 || err != nil {
  1157  				t.Errorf("log format error: %d elements, error %s:\n%s", n, err, contents(severity.InfoLog))
  1158  			}
  1159  			want := fmt.Sprintf(data.format, line)
  1160  			if contents(severity.InfoLog) != want {
  1161  				t.Errorf("InfoS has wrong format: \n got:\t%s\nwant:\t%s", contents(severity.InfoLog), want)
  1162  			}
  1163  		}
  1164  	}
  1165  }
  1166  
  1167  // Test that Verbose.InfoS works as advertised.
  1168  func TestVInfoS(t *testing.T) {
  1169  	defer CaptureState().Restore()
  1170  	setFlags()
  1171  	defer logging.swap(logging.newBuffers())
  1172  	timeNow = func() time.Time {
  1173  		return time.Date(2006, 1, 2, 15, 4, 5, .067890e9, time.Local)
  1174  	}
  1175  	pid = 1234
  1176  	myData := struct {
  1177  		Data string
  1178  	}{
  1179  		Data: `This is some long text
  1180  with a line break.`,
  1181  	}
  1182  	var testDataInfo = []struct {
  1183  		msg        string
  1184  		format     string
  1185  		keysValues []interface{}
  1186  	}{
  1187  		{
  1188  			msg:        "test",
  1189  			format:     "I0102 15:04:05.067890    1234 klog_test.go:%d] \"test\" pod=\"kubedns\"\n",
  1190  			keysValues: []interface{}{"pod", "kubedns"},
  1191  		},
  1192  		{
  1193  			msg:        "test",
  1194  			format:     "I0102 15:04:05.067890    1234 klog_test.go:%d] \"test\" replicaNum=20\n",
  1195  			keysValues: []interface{}{"replicaNum", 20},
  1196  		},
  1197  		{
  1198  			msg:        "test",
  1199  			format:     "I0102 15:04:05.067890    1234 klog_test.go:%d] \"test\" err=\"test error\"\n",
  1200  			keysValues: []interface{}{"err", errors.New("test error")},
  1201  		},
  1202  		{
  1203  			msg: `first message line
  1204  second message line`,
  1205  			format: `I0102 15:04:05.067890    1234 klog_test.go:%d] "first message line\nsecond message line" multiLine=<
  1206  	first value line
  1207  	second value line
  1208   >
  1209  `,
  1210  			keysValues: []interface{}{"multiLine", `first value line
  1211  second value line`},
  1212  		},
  1213  		{
  1214  			msg: `message`,
  1215  			format: `I0102 15:04:05.067890    1234 klog_test.go:%d] "message" myData={"Data":"This is some long text\nwith a line break."}
  1216  `,
  1217  			keysValues: []interface{}{"myData", myData},
  1218  		},
  1219  	}
  1220  
  1221  	require.NoError(t, logging.verbosity.Set("2"))
  1222  
  1223  	for l := Level(0); l < Level(4); l++ {
  1224  		for _, data := range testDataInfo {
  1225  			logging.file[severity.InfoLog] = &flushBuffer{}
  1226  
  1227  			V(l).InfoS(data.msg, data.keysValues...)
  1228  
  1229  			var want string
  1230  			var line int
  1231  			if l <= 2 {
  1232  				n, err := fmt.Sscanf(contents(severity.InfoLog), data.format, &line)
  1233  				if n != 1 || err != nil {
  1234  					t.Errorf("log format error: %d elements, error %s:\n%s", n, err, contents(severity.InfoLog))
  1235  				}
  1236  
  1237  				want = fmt.Sprintf(data.format, line)
  1238  			} else {
  1239  				want = ""
  1240  			}
  1241  			if contents(severity.InfoLog) != want {
  1242  				t.Errorf("V(%d).InfoS has unexpected output:\ngot:\n%s\nwant:\n%s\n", l, contents(severity.InfoLog), want)
  1243  			}
  1244  		}
  1245  	}
  1246  }
  1247  
  1248  // Test that ErrorS and ErrorSDepth work as advertised.
  1249  func TestErrorS(t *testing.T) {
  1250  	defer CaptureState().Restore()
  1251  	setFlags()
  1252  	defer logging.swap(logging.newBuffers())
  1253  	timeNow = func() time.Time {
  1254  		return time.Date(2006, 1, 2, 15, 4, 5, .067890e9, time.Local)
  1255  	}
  1256  	logging.logFile = ""
  1257  	pid = 1234
  1258  
  1259  	functions := []func(err error, msg string, keyAndValues ...interface{}){
  1260  		ErrorS,
  1261  		myErrorS,
  1262  	}
  1263  	for _, f := range functions {
  1264  		var errorList = []struct {
  1265  			err    error
  1266  			format string
  1267  		}{
  1268  			{
  1269  				err:    fmt.Errorf("update status failed"),
  1270  				format: "E0102 15:04:05.067890    1234 klog_test.go:%d] \"Failed to update pod status\" err=\"update status failed\" pod=\"kubedns\"\n",
  1271  			},
  1272  			{
  1273  				err:    nil,
  1274  				format: "E0102 15:04:05.067890    1234 klog_test.go:%d] \"Failed to update pod status\" pod=\"kubedns\"\n",
  1275  			},
  1276  		}
  1277  		for _, e := range errorList {
  1278  			logging.file[severity.ErrorLog] = &flushBuffer{}
  1279  			f(e.err, "Failed to update pod status", "pod", "kubedns")
  1280  			var line int
  1281  			n, err := fmt.Sscanf(contents(severity.ErrorLog), e.format, &line)
  1282  			if n != 1 || err != nil {
  1283  				t.Errorf("log format error: %d elements, error %s:\n%s", n, err, contents(severity.ErrorLog))
  1284  			}
  1285  			want := fmt.Sprintf(e.format, line)
  1286  			if contents(severity.ErrorLog) != want {
  1287  				t.Errorf("ErrorS has wrong format:\ngot:\n%s\nwant:\n%s\n", contents(severity.ErrorLog), want)
  1288  			}
  1289  		}
  1290  	}
  1291  }
  1292  
  1293  func createTestValueOfLoggingT() *loggingT {
  1294  	l := new(loggingT)
  1295  	l.toStderr = true
  1296  	l.alsoToStderr = false
  1297  	l.stderrThreshold = severityValue{
  1298  		Severity: severity.ErrorLog,
  1299  	}
  1300  	l.verbosity = Level(0)
  1301  	l.skipHeaders = false
  1302  	l.skipLogHeaders = false
  1303  	l.addDirHeader = false
  1304  	return l
  1305  }
  1306  
  1307  func createTestValueOfModulePat(p string, li bool, le Level) modulePat {
  1308  	m := modulePat{}
  1309  	m.pattern = p
  1310  	m.literal = li
  1311  	m.level = le
  1312  	return m
  1313  }
  1314  
  1315  func compareModuleSpec(a, b moduleSpec) bool {
  1316  	if len(a.filter) != len(b.filter) {
  1317  		return false
  1318  	}
  1319  
  1320  	for i := 0; i < len(a.filter); i++ {
  1321  		if a.filter[i] != b.filter[i] {
  1322  			return false
  1323  		}
  1324  	}
  1325  
  1326  	return true
  1327  }
  1328  
  1329  func TestSetVState(t *testing.T) {
  1330  	//Target loggingT value
  1331  	want := createTestValueOfLoggingT()
  1332  	want.verbosity = Level(3)
  1333  	want.vmodule.filter = []modulePat{
  1334  		createTestValueOfModulePat("recordio", true, Level(2)),
  1335  		createTestValueOfModulePat("file", true, Level(1)),
  1336  		createTestValueOfModulePat("gfs*", false, Level(3)),
  1337  		createTestValueOfModulePat("gopher*", false, Level(3)),
  1338  	}
  1339  	want.filterLength = 4
  1340  
  1341  	//loggingT value to which test is run
  1342  	target := createTestValueOfLoggingT()
  1343  
  1344  	tf := []modulePat{
  1345  		createTestValueOfModulePat("recordio", true, Level(2)),
  1346  		createTestValueOfModulePat("file", true, Level(1)),
  1347  		createTestValueOfModulePat("gfs*", false, Level(3)),
  1348  		createTestValueOfModulePat("gopher*", false, Level(3)),
  1349  	}
  1350  
  1351  	target.setVState(Level(3), tf, true)
  1352  
  1353  	if want.verbosity != target.verbosity || !compareModuleSpec(want.vmodule, target.vmodule) || want.filterLength != target.filterLength {
  1354  		t.Errorf("setVState method doesn't configure loggingT values' verbosity, vmodule or filterLength:\nwant:\n\tverbosity:\t%v\n\tvmodule:\t%v\n\tfilterLength:\t%v\ngot:\n\tverbosity:\t%v\n\tvmodule:\t%v\n\tfilterLength:\t%v", want.verbosity, want.vmodule, want.filterLength, target.verbosity, target.vmodule, target.filterLength)
  1355  	}
  1356  }
  1357  
  1358  type sampleLogFilter struct{}
  1359  
  1360  func (f *sampleLogFilter) Filter(args []interface{}) []interface{} {
  1361  	for i, arg := range args {
  1362  		v, ok := arg.(string)
  1363  		if ok && strings.Contains(v, "filter me") {
  1364  			args[i] = "[FILTERED]"
  1365  		}
  1366  	}
  1367  	return args
  1368  }
  1369  
  1370  func (f *sampleLogFilter) FilterF(format string, args []interface{}) (string, []interface{}) {
  1371  	return strings.Replace(format, "filter me", "[FILTERED]", 1), f.Filter(args)
  1372  }
  1373  
  1374  func (f *sampleLogFilter) FilterS(msg string, keysAndValues []interface{}) (string, []interface{}) {
  1375  	return strings.Replace(msg, "filter me", "[FILTERED]", 1), f.Filter(keysAndValues)
  1376  }
  1377  
  1378  func TestLogFilter(t *testing.T) {
  1379  	defer CaptureState().Restore()
  1380  	setFlags()
  1381  	defer logging.swap(logging.newBuffers())
  1382  	SetLogFilter(&sampleLogFilter{})
  1383  	funcs := []struct {
  1384  		name     string
  1385  		logFunc  func(args ...interface{})
  1386  		severity severity.Severity
  1387  	}{{
  1388  		name:     "Info",
  1389  		logFunc:  Info,
  1390  		severity: severity.InfoLog,
  1391  	}, {
  1392  		name: "InfoDepth",
  1393  		logFunc: func(args ...interface{}) {
  1394  			InfoDepth(1, args...)
  1395  		},
  1396  		severity: severity.InfoLog,
  1397  	}, {
  1398  		name:     "Infoln",
  1399  		logFunc:  Infoln,
  1400  		severity: severity.InfoLog,
  1401  	}, {
  1402  		name: "Infof",
  1403  		logFunc: func(args ...interface{}) {
  1404  
  1405  			Infof(args[0].(string), args[1:]...)
  1406  		},
  1407  		severity: severity.InfoLog,
  1408  	}, {
  1409  		name: "InfoS",
  1410  		logFunc: func(args ...interface{}) {
  1411  			InfoS(args[0].(string), args[1:]...)
  1412  		},
  1413  		severity: severity.InfoLog,
  1414  	}, {
  1415  		name:     "Warning",
  1416  		logFunc:  Warning,
  1417  		severity: severity.WarningLog,
  1418  	}, {
  1419  		name: "WarningDepth",
  1420  		logFunc: func(args ...interface{}) {
  1421  			WarningDepth(1, args...)
  1422  		},
  1423  		severity: severity.WarningLog,
  1424  	}, {
  1425  		name:     "Warningln",
  1426  		logFunc:  Warningln,
  1427  		severity: severity.WarningLog,
  1428  	}, {
  1429  		name: "Warningf",
  1430  		logFunc: func(args ...interface{}) {
  1431  			Warningf(args[0].(string), args[1:]...)
  1432  		},
  1433  		severity: severity.WarningLog,
  1434  	}, {
  1435  		name:     "Error",
  1436  		logFunc:  Error,
  1437  		severity: severity.ErrorLog,
  1438  	}, {
  1439  		name: "ErrorDepth",
  1440  		logFunc: func(args ...interface{}) {
  1441  			ErrorDepth(1, args...)
  1442  		},
  1443  		severity: severity.ErrorLog,
  1444  	}, {
  1445  		name:     "Errorln",
  1446  		logFunc:  Errorln,
  1447  		severity: severity.ErrorLog,
  1448  	}, {
  1449  		name: "Errorf",
  1450  		logFunc: func(args ...interface{}) {
  1451  			Errorf(args[0].(string), args[1:]...)
  1452  		},
  1453  		severity: severity.ErrorLog,
  1454  	}, {
  1455  		name: "ErrorS",
  1456  		logFunc: func(args ...interface{}) {
  1457  			ErrorS(errors.New("testerror"), args[0].(string), args[1:]...)
  1458  		},
  1459  		severity: severity.ErrorLog,
  1460  	}, {
  1461  		name: "V().Info",
  1462  		logFunc: func(args ...interface{}) {
  1463  			V(0).Info(args...)
  1464  		},
  1465  		severity: severity.InfoLog,
  1466  	}, {
  1467  		name: "V().Infoln",
  1468  		logFunc: func(args ...interface{}) {
  1469  			V(0).Infoln(args...)
  1470  		},
  1471  		severity: severity.InfoLog,
  1472  	}, {
  1473  		name: "V().Infof",
  1474  		logFunc: func(args ...interface{}) {
  1475  			V(0).Infof(args[0].(string), args[1:]...)
  1476  		},
  1477  		severity: severity.InfoLog,
  1478  	}, {
  1479  		name: "V().InfoS",
  1480  		logFunc: func(args ...interface{}) {
  1481  			V(0).InfoS(args[0].(string), args[1:]...)
  1482  		},
  1483  		severity: severity.InfoLog,
  1484  	}, {
  1485  		name: "V().Error",
  1486  		logFunc: func(args ...interface{}) {
  1487  			V(0).Error(errors.New("test error"), args[0].(string), args[1:]...)
  1488  		},
  1489  		severity: severity.ErrorLog,
  1490  	}, {
  1491  		name: "V().ErrorS",
  1492  		logFunc: func(args ...interface{}) {
  1493  			V(0).ErrorS(errors.New("test error"), args[0].(string), args[1:]...)
  1494  		},
  1495  		severity: severity.ErrorLog,
  1496  	}}
  1497  
  1498  	testcases := []struct {
  1499  		name           string
  1500  		args           []interface{}
  1501  		expectFiltered bool
  1502  	}{{
  1503  		args:           []interface{}{"%s:%s", "foo", "bar"},
  1504  		expectFiltered: false,
  1505  	}, {
  1506  		args:           []interface{}{"%s:%s", "foo", "filter me"},
  1507  		expectFiltered: true,
  1508  	}, {
  1509  		args:           []interface{}{"filter me %s:%s", "foo", "bar"},
  1510  		expectFiltered: true,
  1511  	}}
  1512  
  1513  	for _, f := range funcs {
  1514  		for _, tc := range testcases {
  1515  			logging.newBuffers()
  1516  			f.logFunc(tc.args...)
  1517  			got := contains(f.severity, "[FILTERED]")
  1518  			if got != tc.expectFiltered {
  1519  				t.Errorf("%s filter application failed, got %v, want %v", f.name, got, tc.expectFiltered)
  1520  			}
  1521  		}
  1522  	}
  1523  }
  1524  
  1525  func TestInfoWithLogr(t *testing.T) {
  1526  	logger := new(testLogr)
  1527  
  1528  	testDataInfo := []struct {
  1529  		msg      string
  1530  		expected testLogrEntry
  1531  	}{{
  1532  		msg: "foo",
  1533  		expected: testLogrEntry{
  1534  			severity: severity.InfoLog,
  1535  			msg:      "foo",
  1536  		},
  1537  	}, {
  1538  		msg: "",
  1539  		expected: testLogrEntry{
  1540  			severity: severity.InfoLog,
  1541  			msg:      "",
  1542  		},
  1543  	}}
  1544  
  1545  	for _, data := range testDataInfo {
  1546  		t.Run(data.msg, func(t *testing.T) {
  1547  			l := logr.New(logger)
  1548  			defer CaptureState().Restore()
  1549  			SetLogger(l)
  1550  			defer logger.reset()
  1551  
  1552  			Info(data.msg)
  1553  
  1554  			if !reflect.DeepEqual(logger.entries, []testLogrEntry{data.expected}) {
  1555  				t.Errorf("expected: %+v; but got: %+v", []testLogrEntry{data.expected}, logger.entries)
  1556  			}
  1557  		})
  1558  	}
  1559  }
  1560  
  1561  func TestInfoSWithLogr(t *testing.T) {
  1562  	logger := new(testLogr)
  1563  
  1564  	testDataInfo := []struct {
  1565  		msg        string
  1566  		keysValues []interface{}
  1567  		expected   testLogrEntry
  1568  	}{{
  1569  		msg:        "foo",
  1570  		keysValues: []interface{}{},
  1571  		expected: testLogrEntry{
  1572  			severity:      severity.InfoLog,
  1573  			msg:           "foo",
  1574  			keysAndValues: []interface{}{},
  1575  		},
  1576  	}, {
  1577  		msg:        "bar",
  1578  		keysValues: []interface{}{"a", 1},
  1579  		expected: testLogrEntry{
  1580  			severity:      severity.InfoLog,
  1581  			msg:           "bar",
  1582  			keysAndValues: []interface{}{"a", 1},
  1583  		},
  1584  	}}
  1585  
  1586  	for _, data := range testDataInfo {
  1587  		t.Run(data.msg, func(t *testing.T) {
  1588  			defer CaptureState().Restore()
  1589  			l := logr.New(logger)
  1590  			SetLogger(l)
  1591  			defer logger.reset()
  1592  
  1593  			InfoS(data.msg, data.keysValues...)
  1594  
  1595  			if !reflect.DeepEqual(logger.entries, []testLogrEntry{data.expected}) {
  1596  				t.Errorf("expected: %+v; but got: %+v", []testLogrEntry{data.expected}, logger.entries)
  1597  			}
  1598  		})
  1599  	}
  1600  }
  1601  
  1602  func TestErrorSWithLogr(t *testing.T) {
  1603  	logger := new(testLogr)
  1604  
  1605  	testError := errors.New("testError")
  1606  
  1607  	testDataInfo := []struct {
  1608  		err        error
  1609  		msg        string
  1610  		keysValues []interface{}
  1611  		expected   testLogrEntry
  1612  	}{{
  1613  		err:        testError,
  1614  		msg:        "foo1",
  1615  		keysValues: []interface{}{},
  1616  		expected: testLogrEntry{
  1617  			severity:      severity.ErrorLog,
  1618  			msg:           "foo1",
  1619  			keysAndValues: []interface{}{},
  1620  			err:           testError,
  1621  		},
  1622  	}, {
  1623  		err:        testError,
  1624  		msg:        "bar1",
  1625  		keysValues: []interface{}{"a", 1},
  1626  		expected: testLogrEntry{
  1627  			severity:      severity.ErrorLog,
  1628  			msg:           "bar1",
  1629  			keysAndValues: []interface{}{"a", 1},
  1630  			err:           testError,
  1631  		},
  1632  	}, {
  1633  		err:        nil,
  1634  		msg:        "foo2",
  1635  		keysValues: []interface{}{},
  1636  		expected: testLogrEntry{
  1637  			severity:      severity.ErrorLog,
  1638  			msg:           "foo2",
  1639  			keysAndValues: []interface{}{},
  1640  			err:           nil,
  1641  		},
  1642  	}, {
  1643  		err:        nil,
  1644  		msg:        "bar2",
  1645  		keysValues: []interface{}{"a", 1},
  1646  		expected: testLogrEntry{
  1647  			severity:      severity.ErrorLog,
  1648  			msg:           "bar2",
  1649  			keysAndValues: []interface{}{"a", 1},
  1650  			err:           nil,
  1651  		},
  1652  	}}
  1653  
  1654  	for _, data := range testDataInfo {
  1655  		t.Run(data.msg, func(t *testing.T) {
  1656  			defer CaptureState().Restore()
  1657  			l := logr.New(logger)
  1658  			SetLogger(l)
  1659  			defer logger.reset()
  1660  
  1661  			ErrorS(data.err, data.msg, data.keysValues...)
  1662  
  1663  			if !reflect.DeepEqual(logger.entries, []testLogrEntry{data.expected}) {
  1664  				t.Errorf("expected: %+v; but got: %+v", []testLogrEntry{data.expected}, logger.entries)
  1665  			}
  1666  		})
  1667  	}
  1668  }
  1669  
  1670  func TestCallDepthLogr(t *testing.T) {
  1671  	logger := &callDepthTestLogr{}
  1672  	logger.resetCallDepth()
  1673  
  1674  	testCases := []struct {
  1675  		name  string
  1676  		logFn func()
  1677  	}{
  1678  		{
  1679  			name:  "Info log",
  1680  			logFn: func() { Info("info log") },
  1681  		},
  1682  		{
  1683  			name:  "InfoDepth log",
  1684  			logFn: func() { InfoDepth(0, "infodepth log") },
  1685  		},
  1686  		{
  1687  			name:  "InfoSDepth log",
  1688  			logFn: func() { InfoSDepth(0, "infoSDepth log") },
  1689  		},
  1690  		{
  1691  			name:  "Warning log",
  1692  			logFn: func() { Warning("warning log") },
  1693  		},
  1694  		{
  1695  			name:  "WarningDepth log",
  1696  			logFn: func() { WarningDepth(0, "warningdepth log") },
  1697  		},
  1698  		{
  1699  			name:  "Error log",
  1700  			logFn: func() { Error("error log") },
  1701  		},
  1702  		{
  1703  			name:  "ErrorDepth log",
  1704  			logFn: func() { ErrorDepth(0, "errordepth log") },
  1705  		},
  1706  		{
  1707  			name:  "ErrorSDepth log",
  1708  			logFn: func() { ErrorSDepth(0, errors.New("some error"), "errorSDepth log") },
  1709  		},
  1710  	}
  1711  
  1712  	for _, tc := range testCases {
  1713  		t.Run(tc.name, func(t *testing.T) {
  1714  			l := logr.New(logger)
  1715  			defer ClearLogger()
  1716  			SetLogger(l)
  1717  			defer logger.reset()
  1718  			defer logger.resetCallDepth()
  1719  
  1720  			// Keep these lines together.
  1721  			_, wantFile, wantLine, _ := runtime.Caller(0)
  1722  			tc.logFn()
  1723  			wantLine++
  1724  
  1725  			if len(logger.entries) != 1 {
  1726  				t.Errorf("expected a single log entry to be generated, got %d", len(logger.entries))
  1727  			}
  1728  			checkLogrEntryCorrectCaller(t, wantFile, wantLine, logger.entries[0])
  1729  		})
  1730  	}
  1731  }
  1732  
  1733  func TestCallDepthLogrInfoS(t *testing.T) {
  1734  	logger := &callDepthTestLogr{}
  1735  	logger.resetCallDepth()
  1736  	l := logr.New(logger)
  1737  	defer CaptureState().Restore()
  1738  	SetLogger(l)
  1739  
  1740  	// Add wrapper to ensure callDepthTestLogr +2 offset is correct.
  1741  	logFunc := func() {
  1742  		InfoS("infoS log")
  1743  	}
  1744  
  1745  	// Keep these lines together.
  1746  	_, wantFile, wantLine, _ := runtime.Caller(0)
  1747  	logFunc()
  1748  	wantLine++
  1749  
  1750  	if len(logger.entries) != 1 {
  1751  		t.Errorf("expected a single log entry to be generated, got %d", len(logger.entries))
  1752  	}
  1753  	checkLogrEntryCorrectCaller(t, wantFile, wantLine, logger.entries[0])
  1754  }
  1755  
  1756  func TestCallDepthLogrErrorS(t *testing.T) {
  1757  	logger := &callDepthTestLogr{}
  1758  	logger.resetCallDepth()
  1759  	l := logr.New(logger)
  1760  	defer CaptureState().Restore()
  1761  	SetLogger(l)
  1762  
  1763  	// Add wrapper to ensure callDepthTestLogr +2 offset is correct.
  1764  	logFunc := func() {
  1765  		ErrorS(errors.New("some error"), "errorS log")
  1766  	}
  1767  
  1768  	// Keep these lines together.
  1769  	_, wantFile, wantLine, _ := runtime.Caller(0)
  1770  	logFunc()
  1771  	wantLine++
  1772  
  1773  	if len(logger.entries) != 1 {
  1774  		t.Errorf("expected a single log entry to be generated, got %d", len(logger.entries))
  1775  	}
  1776  	checkLogrEntryCorrectCaller(t, wantFile, wantLine, logger.entries[0])
  1777  }
  1778  
  1779  func TestCallDepthLogrGoLog(t *testing.T) {
  1780  	defer CaptureState().Restore()
  1781  	logger := &callDepthTestLogr{}
  1782  	logger.resetCallDepth()
  1783  	l := logr.New(logger)
  1784  	SetLogger(l)
  1785  	CopyStandardLogTo("INFO")
  1786  
  1787  	// Add wrapper to ensure callDepthTestLogr +2 offset is correct.
  1788  	logFunc := func() {
  1789  		stdLog.Print("some log")
  1790  	}
  1791  
  1792  	// Keep these lines together.
  1793  	_, wantFile, wantLine, _ := runtime.Caller(0)
  1794  	logFunc()
  1795  	wantLine++
  1796  
  1797  	if len(logger.entries) != 1 {
  1798  		t.Errorf("expected a single log entry to be generated, got %d", len(logger.entries))
  1799  	}
  1800  	checkLogrEntryCorrectCaller(t, wantFile, wantLine, logger.entries[0])
  1801  	fmt.Println(logger.entries[0])
  1802  }
  1803  
  1804  // Test callDepthTestLogr logs the expected offsets.
  1805  func TestCallDepthTestLogr(t *testing.T) {
  1806  	logger := &callDepthTestLogr{}
  1807  	logger.resetCallDepth()
  1808  
  1809  	logFunc := func() {
  1810  		logger.Info(0, "some info log")
  1811  	}
  1812  	// Keep these lines together.
  1813  	_, wantFile, wantLine, _ := runtime.Caller(0)
  1814  	logFunc()
  1815  	wantLine++
  1816  
  1817  	if len(logger.entries) != 1 {
  1818  		t.Errorf("expected a single log entry to be generated, got %d", len(logger.entries))
  1819  	}
  1820  	checkLogrEntryCorrectCaller(t, wantFile, wantLine, logger.entries[0])
  1821  
  1822  	logger.reset()
  1823  
  1824  	logFunc = func() {
  1825  		logger.Error(errors.New("error"), "some error log")
  1826  	}
  1827  	// Keep these lines together.
  1828  	_, wantFile, wantLine, _ = runtime.Caller(0)
  1829  	logFunc()
  1830  	wantLine++
  1831  
  1832  	if len(logger.entries) != 1 {
  1833  		t.Errorf("expected a single log entry to be generated, got %d", len(logger.entries))
  1834  	}
  1835  	checkLogrEntryCorrectCaller(t, wantFile, wantLine, logger.entries[0])
  1836  }
  1837  
  1838  type testLogr struct {
  1839  	entries []testLogrEntry
  1840  	mutex   sync.Mutex
  1841  }
  1842  
  1843  type testLogrEntry struct {
  1844  	severity      severity.Severity
  1845  	msg           string
  1846  	keysAndValues []interface{}
  1847  	err           error
  1848  }
  1849  
  1850  func (l *testLogr) reset() {
  1851  	l.mutex.Lock()
  1852  	defer l.mutex.Unlock()
  1853  	l.entries = []testLogrEntry{}
  1854  }
  1855  
  1856  func (l *testLogr) Info(_ int, msg string, keysAndValues ...interface{}) {
  1857  	l.mutex.Lock()
  1858  	defer l.mutex.Unlock()
  1859  	l.entries = append(l.entries, testLogrEntry{
  1860  		severity:      severity.InfoLog,
  1861  		msg:           msg,
  1862  		keysAndValues: keysAndValues,
  1863  	})
  1864  }
  1865  
  1866  func (l *testLogr) Error(err error, msg string, keysAndValues ...interface{}) {
  1867  	l.mutex.Lock()
  1868  	defer l.mutex.Unlock()
  1869  	l.entries = append(l.entries, testLogrEntry{
  1870  		severity:      severity.ErrorLog,
  1871  		msg:           msg,
  1872  		keysAndValues: keysAndValues,
  1873  		err:           err,
  1874  	})
  1875  }
  1876  
  1877  func (l *testLogr) Init(logr.RuntimeInfo)                  {}
  1878  func (l *testLogr) Enabled(int) bool                       { return true }
  1879  func (l *testLogr) V(int) logr.Logger                      { panic("not implemented") }
  1880  func (l *testLogr) WithName(string) logr.LogSink           { panic("not implemented") }
  1881  func (l *testLogr) WithValues(...interface{}) logr.LogSink { panic("not implemented") }
  1882  func (l *testLogr) WithCallDepth(int) logr.LogSink         { return l }
  1883  
  1884  var _ logr.LogSink = &testLogr{}
  1885  var _ logr.CallDepthLogSink = &testLogr{}
  1886  
  1887  type callDepthTestLogr struct {
  1888  	testLogr
  1889  	callDepth int
  1890  }
  1891  
  1892  func (l *callDepthTestLogr) resetCallDepth() {
  1893  	l.mutex.Lock()
  1894  	defer l.mutex.Unlock()
  1895  	l.callDepth = 0
  1896  }
  1897  
  1898  func (l *callDepthTestLogr) WithCallDepth(depth int) logr.LogSink {
  1899  	l.mutex.Lock()
  1900  	defer l.mutex.Unlock()
  1901  	// Note: Usually WithCallDepth would be implemented by cloning l
  1902  	// and setting the call depth on the clone. We modify l instead in
  1903  	// this test helper for simplicity.
  1904  	l.callDepth = depth + 1
  1905  	return l
  1906  }
  1907  
  1908  func (l *callDepthTestLogr) Info(_ int, msg string, keysAndValues ...interface{}) {
  1909  	l.mutex.Lock()
  1910  	defer l.mutex.Unlock()
  1911  	// Add 2 to depth for the wrapper function caller and for invocation in
  1912  	// test case.
  1913  	_, file, line, _ := runtime.Caller(l.callDepth + 2)
  1914  	l.entries = append(l.entries, testLogrEntry{
  1915  		severity:      severity.InfoLog,
  1916  		msg:           msg,
  1917  		keysAndValues: append([]interface{}{file, line}, keysAndValues...),
  1918  	})
  1919  }
  1920  
  1921  func (l *callDepthTestLogr) Error(err error, msg string, keysAndValues ...interface{}) {
  1922  	l.mutex.Lock()
  1923  	defer l.mutex.Unlock()
  1924  	// Add 2 to depth for the wrapper function caller and for invocation in
  1925  	// test case.
  1926  	_, file, line, _ := runtime.Caller(l.callDepth + 2)
  1927  	l.entries = append(l.entries, testLogrEntry{
  1928  		severity:      severity.ErrorLog,
  1929  		msg:           msg,
  1930  		keysAndValues: append([]interface{}{file, line}, keysAndValues...),
  1931  		err:           err,
  1932  	})
  1933  }
  1934  
  1935  var _ logr.LogSink = &callDepthTestLogr{}
  1936  var _ logr.CallDepthLogSink = &callDepthTestLogr{}
  1937  
  1938  func checkLogrEntryCorrectCaller(t *testing.T, wantFile string, wantLine int, entry testLogrEntry) {
  1939  	t.Helper()
  1940  
  1941  	want := fmt.Sprintf("%s:%d", wantFile, wantLine)
  1942  	// Log fields contain file and line number as first elements.
  1943  	got := fmt.Sprintf("%s:%d", entry.keysAndValues[0], entry.keysAndValues[1])
  1944  
  1945  	if want != got {
  1946  		t.Errorf("expected file and line %q but got %q", want, got)
  1947  	}
  1948  }
  1949  
  1950  // existedFlag contains all existed flag, without KlogPrefix
  1951  var existedFlag = map[string]struct{}{
  1952  	"log_dir":           {},
  1953  	"add_dir_header":    {},
  1954  	"alsologtostderr":   {},
  1955  	"log_backtrace_at":  {},
  1956  	"log_file":          {},
  1957  	"log_file_max_size": {},
  1958  	"logtostderr":       {},
  1959  	"one_output":        {},
  1960  	"skip_headers":      {},
  1961  	"skip_log_headers":  {},
  1962  	"stderrthreshold":   {},
  1963  	"v":                 {},
  1964  	"vmodule":           {},
  1965  }
  1966  
  1967  // KlogPrefix define new flag prefix
  1968  const KlogPrefix string = "klog"
  1969  
  1970  // TestKlogFlagPrefix check every klog flag's prefix, exclude flag in existedFlag
  1971  func TestKlogFlagPrefix(t *testing.T) {
  1972  	fs := &flag.FlagSet{}
  1973  	InitFlags(fs)
  1974  	fs.VisitAll(func(f *flag.Flag) {
  1975  		if _, found := existedFlag[f.Name]; !found {
  1976  			if !strings.HasPrefix(f.Name, KlogPrefix) {
  1977  				t.Errorf("flag %s not have klog prefix: %s", f.Name, KlogPrefix)
  1978  			}
  1979  		}
  1980  	})
  1981  }
  1982  
  1983  func TestKObjs(t *testing.T) {
  1984  	tests := []struct {
  1985  		name string
  1986  		obj  interface{}
  1987  		want []ObjectRef
  1988  	}{
  1989  		{
  1990  			name: "test for KObjs function with KMetadata slice",
  1991  			obj: []test.KMetadataMock{
  1992  				{
  1993  					Name: "kube-dns",
  1994  					NS:   "kube-system",
  1995  				},
  1996  				{
  1997  					Name: "mi-conf",
  1998  				},
  1999  				{},
  2000  			},
  2001  			want: []ObjectRef{
  2002  				{
  2003  					Name:      "kube-dns",
  2004  					Namespace: "kube-system",
  2005  				},
  2006  				{
  2007  					Name: "mi-conf",
  2008  				},
  2009  				{},
  2010  			},
  2011  		},
  2012  		{
  2013  			name: "test for KObjs function with KMetadata pointer slice",
  2014  			obj: []*test.KMetadataMock{
  2015  				{
  2016  					Name: "kube-dns",
  2017  					NS:   "kube-system",
  2018  				},
  2019  				{
  2020  					Name: "mi-conf",
  2021  				},
  2022  				nil,
  2023  			},
  2024  			want: []ObjectRef{
  2025  				{
  2026  					Name:      "kube-dns",
  2027  					Namespace: "kube-system",
  2028  				},
  2029  				{
  2030  					Name: "mi-conf",
  2031  				},
  2032  				{},
  2033  			},
  2034  		},
  2035  		{
  2036  			name: "test for KObjs function with slice does not implement KMetadata",
  2037  			obj:  []int{1, 2, 3, 4, 6},
  2038  			want: nil,
  2039  		},
  2040  		{
  2041  			name: "test for KObjs function with interface",
  2042  			obj:  "test case",
  2043  			want: nil,
  2044  		},
  2045  		{
  2046  			name: "test for KObjs function with nil",
  2047  			obj:  nil,
  2048  			want: nil,
  2049  		},
  2050  	}
  2051  
  2052  	for _, tt := range tests {
  2053  		t.Run(tt.name, func(t *testing.T) {
  2054  			if !reflect.DeepEqual(KObjs(tt.obj), tt.want) {
  2055  				t.Errorf("\nwant:\t %v\n got:\t %v", tt.want, KObjs(tt.obj))
  2056  			}
  2057  		})
  2058  	}
  2059  }
  2060  
  2061  // Benchmark test for lock with/without defer
  2062  type structWithLock struct {
  2063  	m sync.Mutex
  2064  	n int64
  2065  }
  2066  
  2067  func BenchmarkWithoutDeferUnLock(b *testing.B) {
  2068  	s := structWithLock{}
  2069  	for i := 0; i < b.N; i++ {
  2070  		s.addWithoutDefer()
  2071  	}
  2072  }
  2073  
  2074  func BenchmarkWithDeferUnLock(b *testing.B) {
  2075  	s := structWithLock{}
  2076  	for i := 0; i < b.N; i++ {
  2077  		s.addWithDefer()
  2078  	}
  2079  }
  2080  
  2081  func (s *structWithLock) addWithoutDefer() {
  2082  	s.m.Lock()
  2083  	s.n++
  2084  	s.m.Unlock()
  2085  }
  2086  
  2087  func (s *structWithLock) addWithDefer() {
  2088  	s.m.Lock()
  2089  	defer s.m.Unlock()
  2090  	s.n++
  2091  }
  2092  
  2093  func TestFlushDaemon(t *testing.T) {
  2094  	for sev := severity.InfoLog; sev < severity.FatalLog; sev++ {
  2095  		flushed := make(chan struct{}, 1)
  2096  		spyFunc := func() {
  2097  			flushed <- struct{}{}
  2098  		}
  2099  		testClock := testingclock.NewFakeClock(time.Now())
  2100  		testLog := loggingT{
  2101  			settings: settings{
  2102  				flushInterval: time.Second,
  2103  			},
  2104  			flushD: newFlushDaemon(spyFunc, testClock),
  2105  		}
  2106  
  2107  		// Calling testLog will call createFile, which should start the daemon.
  2108  		testLog.print(sev, nil, nil, "x")
  2109  
  2110  		if !testLog.flushD.isRunning() {
  2111  			t.Error("expected flushD to be running")
  2112  		}
  2113  
  2114  		timer := time.NewTimer(10 * time.Second)
  2115  		defer timer.Stop()
  2116  		testClock.Step(time.Second)
  2117  		select {
  2118  		case <-flushed:
  2119  		case <-timer.C:
  2120  			t.Fatal("flushDaemon didn't call flush function on tick")
  2121  		}
  2122  
  2123  		timer = time.NewTimer(10 * time.Second)
  2124  		defer timer.Stop()
  2125  		testClock.Step(time.Second)
  2126  		select {
  2127  		case <-flushed:
  2128  		case <-timer.C:
  2129  			t.Fatal("flushDaemon didn't call flush function on second tick")
  2130  		}
  2131  
  2132  		timer = time.NewTimer(10 * time.Second)
  2133  		defer timer.Stop()
  2134  		testLog.flushD.stop()
  2135  		select {
  2136  		case <-flushed:
  2137  		case <-timer.C:
  2138  			t.Fatal("flushDaemon didn't call flush function one last time on stop")
  2139  		}
  2140  	}
  2141  }
  2142  
  2143  func TestStopFlushDaemon(t *testing.T) {
  2144  	logging.flushD.stop()
  2145  	logging.flushD = newFlushDaemon(func() {}, nil)
  2146  	logging.flushD.run(time.Second)
  2147  	if !logging.flushD.isRunning() {
  2148  		t.Error("expected flushD to be running")
  2149  	}
  2150  	StopFlushDaemon()
  2151  	if logging.flushD.isRunning() {
  2152  		t.Error("expected flushD to be stopped")
  2153  	}
  2154  }
  2155  
  2156  func TestCaptureState(t *testing.T) {
  2157  	var fs flag.FlagSet
  2158  	InitFlags(&fs)
  2159  
  2160  	// Capture state.
  2161  	oldState := map[string]string{}
  2162  	fs.VisitAll(func(f *flag.Flag) {
  2163  		oldState[f.Name] = f.Value.String()
  2164  	})
  2165  	originalLogger := Background()
  2166  	file := logging.file
  2167  
  2168  	// And through dedicated API.
  2169  	// Ensure we always restore.
  2170  	state := CaptureState()
  2171  	defer state.Restore()
  2172  
  2173  	// Change state.
  2174  	for name, value := range map[string]string{
  2175  		// All of these are non-standard values.
  2176  		"v":                 "10",
  2177  		"vmodule":           "abc=2",
  2178  		"log_dir":           "/tmp",
  2179  		"log_file_max_size": "10",
  2180  		"logtostderr":       "false",
  2181  		"alsologtostderr":   "true",
  2182  		"add_dir_header":    "true",
  2183  		"skip_headers":      "true",
  2184  		"one_output":        "true",
  2185  		"skip_log_headers":  "true",
  2186  		"stderrthreshold":   "1",
  2187  		"log_backtrace_at":  "foobar.go:100",
  2188  	} {
  2189  		f := fs.Lookup(name)
  2190  		if f == nil {
  2191  			t.Fatalf("could not look up %q", name)
  2192  		}
  2193  		currentValue := f.Value.String()
  2194  		if currentValue == value {
  2195  			t.Fatalf("%q is already set to non-default %q?!", name, value)
  2196  		}
  2197  		if err := f.Value.Set(value); err != nil {
  2198  			t.Fatalf("setting %q to %q: %v", name, value, err)
  2199  		}
  2200  	}
  2201  	StartFlushDaemon(time.Minute)
  2202  	if !logging.flushD.isRunning() {
  2203  		t.Error("Flush daemon should have been started.")
  2204  	}
  2205  	logger := logr.Discard()
  2206  	SetLoggerWithOptions(logger, ContextualLogger(true))
  2207  	actualLogger := Background()
  2208  	if logger != actualLogger {
  2209  		t.Errorf("Background logger should be %v, got %v", logger, actualLogger)
  2210  	}
  2211  	buffer := bytes.Buffer{}
  2212  	SetOutput(&buffer)
  2213  	if file == logging.file {
  2214  		t.Error("Output files should have been modified.")
  2215  	}
  2216  
  2217  	// Let klog restore the state.
  2218  	state.Restore()
  2219  
  2220  	// Verify that the original state is back.
  2221  	fs.VisitAll(func(f *flag.Flag) {
  2222  		oldValue := oldState[f.Name]
  2223  		currentValue := f.Value.String()
  2224  		if oldValue != currentValue {
  2225  			t.Errorf("%q should have been restored to %q, is %q instead", f.Name, oldValue, currentValue)
  2226  		}
  2227  	})
  2228  	if logging.flushD.isRunning() {
  2229  		t.Error("Flush daemon should have been stopped.")
  2230  	}
  2231  	actualLogger = Background()
  2232  	if originalLogger != actualLogger {
  2233  		t.Errorf("Background logger should be %v, got %v", originalLogger, actualLogger)
  2234  	}
  2235  	if file != logging.file {
  2236  		t.Errorf("Output files should have been restored to %v, got %v", file, logging.file)
  2237  	}
  2238  }
  2239  
  2240  func TestSettingsDeepCopy(t *testing.T) {
  2241  	logger := logr.Discard()
  2242  
  2243  	settings := settings{
  2244  		logger: &logWriter{Logger: logger},
  2245  		vmodule: moduleSpec{
  2246  			filter: []modulePat{
  2247  				{pattern: "a"},
  2248  				{pattern: "b"},
  2249  				{pattern: "c"},
  2250  			},
  2251  		},
  2252  	}
  2253  	clone := settings.deepCopy()
  2254  	if !reflect.DeepEqual(settings, clone) {
  2255  		t.Fatalf("Copy not identical to original settings. Original:\n    %+v\nCopy:    %+v", settings, clone)
  2256  	}
  2257  	settings.vmodule.filter[1].pattern = "x"
  2258  	if clone.vmodule.filter[1].pattern == settings.vmodule.filter[1].pattern {
  2259  		t.Fatal("Copy should not have shared vmodule.filter.")
  2260  	}
  2261  }
  2262  

View as plain text