testinglogger.go

Documentation: k8s.io/klog/v2/ktesting

     1  /*
     2  Copyright 2019 The Kubernetes Authors.
     3  Copyright 2020 Intel Corporation.
     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  
    18  // Package testinglogger contains an implementation of the logr interface
    19  // which is logging through a function like testing.TB.Log function.
    20  // Therefore it can be used in standard Go tests and Gingko test suites
    21  // to ensure that output is associated with the currently running test.
    22  //
    23  // In addition, the log data is captured in a buffer and can be used by the
    24  // test to verify that the code under test is logging as expected. To get
    25  // access to that data, cast the LogSink into the Underlier type and retrieve
    26  // it:
    27  //
    28  //	logger := ktesting.NewLogger(...)
    29  //	if testingLogger, ok := logger.GetSink().(ktesting.Underlier); ok {
    30  //	    t := testingLogger.GetUnderlying()
    31  //	    buffer := testingLogger.GetBuffer()
    32  //	    text := buffer.String()
    33  //	    log := buffer.Data()
    34  //
    35  // Serialization of the structured log parameters is done in the same way
    36  // as for klog.InfoS.
    37  package ktesting
    38  
    39  import (
    40  	"fmt"
    41  	"strings"
    42  	"sync"
    43  	"time"
    44  
    45  	"github.com/go-logr/logr"
    46  
    47  	"k8s.io/klog/v2"
    48  	"k8s.io/klog/v2/internal/buffer"
    49  	"k8s.io/klog/v2/internal/dbg"
    50  	"k8s.io/klog/v2/internal/serialize"
    51  	"k8s.io/klog/v2/internal/severity"
    52  	"k8s.io/klog/v2/internal/verbosity"
    53  )
    54  
    55  // TL is the relevant subset of testing.TB.
    56  type TL interface {
    57  	Helper()
    58  	Log(args ...interface{})
    59  }
    60  
    61  // NopTL implements TL with empty stubs. It can be used when only capturing
    62  // output in memory is relevant.
    63  type NopTL struct{}
    64  
    65  func (n NopTL) Helper()            {}
    66  func (n NopTL) Log(...interface{}) {}
    67  
    68  var _ TL = NopTL{}
    69  
    70  // BufferTL implements TL with an in-memory buffer.
    71  type BufferTL struct {
    72  	strings.Builder
    73  }
    74  
    75  func (n *BufferTL) Helper() {}
    76  func (n *BufferTL) Log(args ...interface{}) {
    77  	n.Builder.WriteString(fmt.Sprintln(args...))
    78  }
    79  
    80  var _ TL = &BufferTL{}
    81  
    82  // NewLogger constructs a new logger for the given test interface.
    83  //
    84  // Beware that testing.T does not support logging after the test that
    85  // it was created for has completed. If a test leaks goroutines
    86  // and those goroutines log something after test completion,
    87  // that output will be printed via the global klog logger with
    88  // `<test name> leaked goroutine` as prefix.
    89  //
    90  // Verbosity can be modified at any time through the Config.V and
    91  // Config.VModule API.
    92  func NewLogger(t TL, c *Config) logr.Logger {
    93  	l := tlogger{
    94  		shared: &tloggerShared{
    95  			t:      t,
    96  			config: c,
    97  		},
    98  	}
    99  	if c.co.anyToString != nil {
   100  		l.shared.formatter.AnyToStringHook = c.co.anyToString
   101  	}
   102  
   103  	type testCleanup interface {
   104  		Cleanup(func())
   105  		Name() string
   106  	}
   107  
   108  	// Stopping the logging is optional and only done (and required)
   109  	// for testing.T/B/F.
   110  	if tb, ok := t.(testCleanup); ok {
   111  		tb.Cleanup(l.shared.stop)
   112  		l.shared.testName = tb.Name()
   113  	}
   114  	return logr.New(l)
   115  }
   116  
   117  // Buffer stores log entries as formatted text and structured data.
   118  // It is safe to use this concurrently.
   119  type Buffer interface {
   120  	// String returns the log entries in a format that is similar to the
   121  	// klog text output.
   122  	String() string
   123  
   124  	// Data returns the log entries as structs.
   125  	Data() Log
   126  }
   127  
   128  // Log contains log entries in the order in which they were generated.
   129  type Log []LogEntry
   130  
   131  // DeepCopy returns a copy of the log. The error instance and key/value
   132  // pairs remain shared.
   133  func (l Log) DeepCopy() Log {
   134  	log := make(Log, 0, len(l))
   135  	log = append(log, l...)
   136  	return log
   137  }
   138  
   139  // LogEntry represents all information captured for a log entry.
   140  type LogEntry struct {
   141  	// Timestamp stores the time when the log entry was created.
   142  	Timestamp time.Time
   143  
   144  	// Type is either LogInfo or LogError.
   145  	Type LogType
   146  
   147  	// Prefix contains the WithName strings concatenated with a slash.
   148  	Prefix string
   149  
   150  	// Message is the fixed log message string.
   151  	Message string
   152  
   153  	// Verbosity is always 0 for LogError.
   154  	Verbosity int
   155  
   156  	// Err is always nil for LogInfo. It may or may not be
   157  	// nil for LogError.
   158  	Err error
   159  
   160  	// WithKVList are the concatenated key/value pairs from WithValues
   161  	// calls. It's guaranteed to have an even number of entries because
   162  	// the logger ensures that when WithValues is called.
   163  	WithKVList []interface{}
   164  
   165  	// ParameterKVList are the key/value pairs passed into the call,
   166  	// without any validation.
   167  	ParameterKVList []interface{}
   168  }
   169  
   170  // LogType determines whether a log entry was created with an Error or Info
   171  // call.
   172  type LogType string
   173  
   174  const (
   175  	// LogError is the special value used for Error log entries.
   176  	LogError = LogType("ERROR")
   177  
   178  	// LogInfo is the special value used for Info log entries.
   179  	LogInfo = LogType("INFO")
   180  )
   181  
   182  // Underlier is implemented by the LogSink of this logger. It provides access
   183  // to additional APIs that are normally hidden behind the Logger API.
   184  type Underlier interface {
   185  	// GetUnderlying returns the testing instance that logging goes to.
   186  	// It returns nil when the test has completed already.
   187  	GetUnderlying() TL
   188  
   189  	// GetBuffer grants access to the in-memory copy of the log entries.
   190  	GetBuffer() Buffer
   191  }
   192  
   193  type logBuffer struct {
   194  	mutex sync.Mutex
   195  	text  strings.Builder
   196  	log   Log
   197  }
   198  
   199  func (b *logBuffer) String() string {
   200  	b.mutex.Lock()
   201  	defer b.mutex.Unlock()
   202  	return b.text.String()
   203  }
   204  
   205  func (b *logBuffer) Data() Log {
   206  	b.mutex.Lock()
   207  	defer b.mutex.Unlock()
   208  	return b.log.DeepCopy()
   209  }
   210  
   211  // tloggerShared holds values that are the same for all LogSink instances. It
   212  // gets referenced by pointer in the tlogger struct.
   213  type tloggerShared struct {
   214  	// mutex protects access to t.
   215  	mutex sync.Mutex
   216  
   217  	// t gets cleared when the test is completed.
   218  	t TL
   219  
   220  	// The time when the test completed.
   221  	stopTime time.Time
   222  
   223  	// We warn once when a leaked goroutine logs after test completion.
   224  	//
   225  	// Not terminating immediately is fairly normal: many controllers
   226  	// log "terminating" messages while they shut down, which often is
   227  	// right after test completion, if that is when the test cancels the
   228  	// context and then doesn't wait for goroutines (which is often
   229  	// not possible).
   230  	//
   231  	// Therefore there is the [stopGracePeriod] during which messages get
   232  	// logged to the global logger without the warning.
   233  	goroutineWarningDone bool
   234  
   235  	formatter serialize.Formatter
   236  	testName  string
   237  	config    *Config
   238  	buffer    logBuffer
   239  	callDepth int
   240  }
   241  
   242  // Log output of a leaked goroutine during this period after test completion
   243  // does not trigger the warning.
   244  const stopGracePeriod = 10 * time.Second
   245  
   246  func (ls *tloggerShared) stop() {
   247  	ls.mutex.Lock()
   248  	defer ls.mutex.Unlock()
   249  	ls.t = nil
   250  	ls.stopTime = time.Now()
   251  }
   252  
   253  // tlogger is the actual LogSink implementation.
   254  type tlogger struct {
   255  	shared *tloggerShared
   256  	prefix string
   257  	values []interface{}
   258  }
   259  
   260  // fallbackLogger is called while l.shared.mutex is locked and after it has
   261  // been determined that the original testing.TB is no longer usable.
   262  func (l tlogger) fallbackLogger() logr.Logger {
   263  	logger := klog.Background().WithValues(l.values...).WithName(l.shared.testName + " leaked goroutine")
   264  	if l.prefix != "" {
   265  		logger = logger.WithName(l.prefix)
   266  	}
   267  	// Skip direct caller (= Error or Info) plus the logr wrapper.
   268  	logger = logger.WithCallDepth(l.shared.callDepth + 1)
   269  
   270  	if !l.shared.goroutineWarningDone {
   271  		duration := time.Since(l.shared.stopTime)
   272  		if duration > stopGracePeriod {
   273  
   274  			logger.WithCallDepth(1).Info("WARNING: test kept at least one goroutine running after test completion", "timeSinceCompletion", duration.Round(time.Second), "callstack", string(dbg.Stacks(false)))
   275  			l.shared.goroutineWarningDone = true
   276  		}
   277  	}
   278  	return logger
   279  }
   280  
   281  func (l tlogger) Init(info logr.RuntimeInfo) {
   282  	l.shared.callDepth = info.CallDepth
   283  }
   284  
   285  func (l tlogger) GetCallStackHelper() func() {
   286  	l.shared.mutex.Lock()
   287  	defer l.shared.mutex.Unlock()
   288  	if l.shared.t == nil {
   289  		return func() {}
   290  	}
   291  
   292  	return l.shared.t.Helper
   293  }
   294  
   295  func (l tlogger) Info(level int, msg string, kvList ...interface{}) {
   296  	l.shared.mutex.Lock()
   297  	defer l.shared.mutex.Unlock()
   298  	if l.shared.t == nil {
   299  		l.fallbackLogger().V(level).Info(msg, kvList...)
   300  		return
   301  	}
   302  
   303  	l.shared.t.Helper()
   304  	buf := buffer.GetBuffer()
   305  	l.shared.formatter.MergeAndFormatKVs(&buf.Buffer, l.values, kvList)
   306  	l.log(LogInfo, msg, level, buf, nil, kvList)
   307  }
   308  
   309  func (l tlogger) Enabled(level int) bool {
   310  	return l.shared.config.vstate.Enabled(verbosity.Level(level), 1)
   311  }
   312  
   313  func (l tlogger) Error(err error, msg string, kvList ...interface{}) {
   314  	l.shared.mutex.Lock()
   315  	defer l.shared.mutex.Unlock()
   316  	if l.shared.t == nil {
   317  		l.fallbackLogger().Error(err, msg, kvList...)
   318  		return
   319  	}
   320  
   321  	l.shared.t.Helper()
   322  	buf := buffer.GetBuffer()
   323  	if err != nil {
   324  		l.shared.formatter.KVFormat(&buf.Buffer, "err", err)
   325  	}
   326  	l.shared.formatter.MergeAndFormatKVs(&buf.Buffer, l.values, kvList)
   327  	l.log(LogError, msg, 0, buf, err, kvList)
   328  }
   329  
   330  func (l tlogger) log(what LogType, msg string, level int, buf *buffer.Buffer, err error, kvList []interface{}) {
   331  	l.shared.t.Helper()
   332  	s := severity.InfoLog
   333  	if what == LogError {
   334  		s = severity.ErrorLog
   335  	}
   336  	args := []interface{}{buf.SprintHeader(s, time.Now())}
   337  	if l.prefix != "" {
   338  		args = append(args, l.prefix+":")
   339  	}
   340  	args = append(args, msg)
   341  	if buf.Len() > 0 {
   342  		// Skip leading space inserted by serialize.KVListFormat.
   343  		args = append(args, string(buf.Bytes()[1:]))
   344  	}
   345  	l.shared.t.Log(args...)
   346  
   347  	if !l.shared.config.co.bufferLogs {
   348  		return
   349  	}
   350  
   351  	l.shared.buffer.mutex.Lock()
   352  	defer l.shared.buffer.mutex.Unlock()
   353  
   354  	// Store as text.
   355  	l.shared.buffer.text.WriteString(string(what))
   356  	for i := 1; i < len(args); i++ {
   357  		l.shared.buffer.text.WriteByte(' ')
   358  		l.shared.buffer.text.WriteString(args[i].(string))
   359  	}
   360  	lastArg := args[len(args)-1].(string)
   361  	if lastArg[len(lastArg)-1] != '\n' {
   362  		l.shared.buffer.text.WriteByte('\n')
   363  	}
   364  
   365  	// Store as raw data.
   366  	l.shared.buffer.log = append(l.shared.buffer.log,
   367  		LogEntry{
   368  			Timestamp:       time.Now(),
   369  			Type:            what,
   370  			Prefix:          l.prefix,
   371  			Message:         msg,
   372  			Verbosity:       level,
   373  			Err:             err,
   374  			WithKVList:      l.values,
   375  			ParameterKVList: kvList,
   376  		},
   377  	)
   378  }
   379  
   380  // WithName returns a new logr.Logger with the specified name appended.  klogr
   381  // uses '/' characters to separate name elements.  Callers should not pass '/'
   382  // in the provided name string, but this library does not actually enforce that.
   383  func (l tlogger) WithName(name string) logr.LogSink {
   384  	if len(l.prefix) > 0 {
   385  		l.prefix = l.prefix + "/"
   386  	}
   387  	l.prefix += name
   388  	return l
   389  }
   390  
   391  func (l tlogger) WithValues(kvList ...interface{}) logr.LogSink {
   392  	l.values = serialize.WithValues(l.values, kvList)
   393  	return l
   394  }
   395  
   396  func (l tlogger) GetUnderlying() TL {
   397  	return l.shared.t
   398  }
   399  
   400  func (l tlogger) GetBuffer() Buffer {
   401  	return &l.shared.buffer
   402  }
   403  
   404  var _ logr.LogSink = &tlogger{}
   405  var _ logr.CallStackHelperLogSink = &tlogger{}
   406  var _ Underlier = &tlogger{}
   407
View as plain text