diff --git a/ktesting/example_test.go b/ktesting/example_test.go new file mode 100644 index 000000000..fdfe84ac7 --- /dev/null +++ b/ktesting/example_test.go @@ -0,0 +1,67 @@ +/* +Copyright 2022 The Kubernetes Authors. + +Licensed under the Apache License, Version 2.0 (the "License"); +you may not use this file except in compliance with the License. +You may obtain a copy of the License at + + http://www.apache.org/licenses/LICENSE-2.0 + +Unless required by applicable law or agreed to in writing, software +distributed under the License is distributed on an "AS IS" BASIS, +WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +See the License for the specific language governing permissions and +limitations under the License. +*/ + +package ktesting_test + +import ( + "errors" + "fmt" + "time" + + "k8s.io/klog/v2/ktesting" +) + +func ExampleUnderlier() { + logger := ktesting.NewLogger(ktesting.NopTL{}, ktesting.NewConfig()) + + logger.Error(errors.New("failure"), "I failed", "what", "something") + logger.WithValues("request", 42).WithValues("anotherValue", "fish").Info("hello world") + logger.WithName("example").Info("with name") + logger.V(1).Info("higher verbosity") + + testingLogger, ok := logger.GetSink().(ktesting.Underlier) + if !ok { + panic("Should have had a ktesting LogSink!?") + } + + t := testingLogger.GetUnderlying() + t.Log("This goes to /dev/null...") + + buffer := testingLogger.GetBuffer() + fmt.Printf("%s\n", buffer.String()) + + log := buffer.Data() + for i, entry := range log { + if i > 0 && + entry.Timestamp.Sub(log[i-1].Timestamp).Nanoseconds() < 0 { + fmt.Printf("Unexpected timestamp order: #%d %s > #%d %s", i-1, log[i-1].Timestamp, i, entry.Timestamp) + } + // Strip varying time stamp before dumping the struct. + entry.Timestamp = time.Time{} + fmt.Printf("log entry #%d: %+v\n", i, entry) + } + + // Output: + // ERROR I failed err="failure" what="something" + // INFO hello world request=42 anotherValue="fish" + // INFO example: with name + // INFO higher verbosity + // + // log entry #0: {Timestamp:0001-01-01 00:00:00 +0000 UTC Type:ERROR Prefix: Message:I failed Verbosity:0 Err:failure KVList:[what something]} + // log entry #1: {Timestamp:0001-01-01 00:00:00 +0000 UTC Type:INFO Prefix: Message:hello world Verbosity:0 Err: KVList:[request 42 anotherValue fish]} + // log entry #2: {Timestamp:0001-01-01 00:00:00 +0000 UTC Type:INFO Prefix:example Message:with name Verbosity:0 Err: KVList:[]} + // log entry #3: {Timestamp:0001-01-01 00:00:00 +0000 UTC Type:INFO Prefix: Message:higher verbosity Verbosity:1 Err: KVList:[]} +} diff --git a/ktesting/testinglogger.go b/ktesting/testinglogger.go index d796f60aa..901ed06b8 100644 --- a/ktesting/testinglogger.go +++ b/ktesting/testinglogger.go @@ -20,6 +20,17 @@ limitations under the License. // Therefore it can be used in standard Go tests and Gingko test suites // to ensure that output is associated with the currently running test. // +// In addition, the log data is captured and can be used by the test to verify +// that the code that is being tested is logging as expected. To get access to +// that data, cast the LogSink into the Underlier type and retrieve it: +// +// logger := ktesting.NewLogger(...) +// if underlier, ok := logger.GetSink().(ktesting.Underlier); ok { +// t := underlier.GetUnderlying() +// buffer := underlier.GetBuffer() +// text := buffer.String() +// log := buffer.Data() +// // Serialization of the structured log parameters is done in the same way // as for klog.InfoS. // @@ -31,6 +42,9 @@ package ktesting import ( "bytes" + "strings" + "sync" + "time" "github.com/go-logr/logr" @@ -49,6 +63,20 @@ type TL interface { Log(args ...interface{}) } +// NopTL implements TL with empty stubs. It can be used when only capturing +// output in memory is relevant. +// +// Experimental +// +// Notice: This type is EXPERIMENTAL and may be changed or removed in a +// later release. +type NopTL struct{} + +func (n NopTL) Helper() {} +func (n NopTL) Log(args ...interface{}) {} + +var _TL = NopTL{} + // NewLogger constructs a new logger for the given test interface. // // Experimental @@ -61,14 +89,145 @@ func NewLogger(t TL, c *Config) logr.Logger { prefix: "", values: nil, config: c, + buffer: new(buffer), }) } +// Buffer stores log entries as formatted text and structured data. +// It is safe to use this concurrently. +// +// Experimental +// +// Notice: This interface is EXPERIMENTAL and may be changed or removed in a +// later release. +type Buffer interface { + // String returns the log entries in the klog text + // output. The logger options determine whether + // this includes the header with time stamps. + String() string + + // Data returns the log entries as structs. + Data() Log +} + +// Log contains log entries in the order in which they were generated. +// +// Experimental +// +// Notice: This type is EXPERIMENTAL and may be changed or removed in a +// later release. +type Log []LogEntry + +// DeepCopy returns a copy of the log. The error instance and key/value +// pairs remain shared. +// +// Experimental +// +// Notice: This function is EXPERIMENTAL and may be changed or removed in a +// later release. +func (l Log) DeepCopy() Log { + log := make(Log, 0, len(l)) + log = append(log, l...) + return log +} + +// LogEntry represents all information captured for a log entry. +// +// Experimental +// +// Notice: This type is EXPERIMENTAL and may be changed or removed in a +// later release. +type LogEntry struct { + // Timestamp stores the time when the log entry was created. + Timestamp time.Time + + // Type is either LogInfo or LogError. + Type LogType + + // Prefix contains the WithName strings concatenated with a slash. + Prefix string + + // Message is the fixed log message string. + Message string + + // Verbosity is always 0 for LogError. + Verbosity int + + // Err is always nil for LogInfo. It may or may not be + // nil for LogError. + Err error + + // KVList are the concatenated key/value pairs from WithValues and the + // call itself, without any validation. + KVList []interface{} +} + +// LogType determines whether a log entry was created with an Error or Info +// call. +// +// Experimental +// +// Notice: This type is EXPERIMENTAL and may be changed or removed in a +// later release. +type LogType string + +const ( + // LogError is the special value used for Error log entries. + // + // Experimental + // + // Notice: This value is EXPERIMENTAL and may be changed or removed in + // a later release. + LogError = LogType("ERROR") + + // LogInfo is the special value used for Info log entries. + // + // Experimental + // + // Notice: This value is EXPERIMENTAL and may be changed or removed in + // a later release. + LogInfo = LogType("INFO") +) + +// Underlier is implemented by the LogSink of this logger. It provides access +// to additional APIs that are normally hidden behind the Logger API. +// +// Experimental +// +// Notice: This type is EXPERIMENTAL and may be changed or removed in a +// later release. +type Underlier interface { + // GetUnderlying returns the testing instance that logging goes to. + GetUnderlying() TL + + // GetBuffer grants access to the in-memory copy of the log entries. + GetBuffer() Buffer +} + +type buffer struct { + mutex sync.Mutex + text strings.Builder + log Log +} + +func (b *buffer) String() string { + b.mutex.Lock() + defer b.mutex.Unlock() + return b.text.String() +} + +func (b *buffer) Data() Log { + b.mutex.Lock() + defer b.mutex.Unlock() + return b.log.DeepCopy() +} + type tlogger struct { t TL prefix string values []interface{} config *Config + buffer *buffer } func (l *tlogger) Init(info logr.RuntimeInfo) { @@ -83,7 +242,7 @@ func (l *tlogger) Info(level int, msg string, kvList ...interface{}) { buffer := &bytes.Buffer{} merged := serialize.MergeKVs(l.values, kvList) serialize.KVListFormat(buffer, merged...) - l.log("INFO", msg, buffer) + l.log(LogInfo, msg, level, buffer, nil, kvList) } func (l *tlogger) Enabled(level int) bool { @@ -98,10 +257,10 @@ func (l *tlogger) Error(err error, msg string, kvList ...interface{}) { } merged := serialize.MergeKVs(l.values, kvList) serialize.KVListFormat(buffer, merged...) - l.log("ERROR", msg, buffer) + l.log(LogError, msg, 0, buffer, err, kvList) } -func (l *tlogger) log(what, msg string, buffer *bytes.Buffer) { +func (l *tlogger) log(what LogType, msg string, level int, buffer *bytes.Buffer, err error, kvList []interface{}) { l.t.Helper() args := []interface{}{what} if l.prefix != "" { @@ -113,6 +272,33 @@ func (l *tlogger) log(what, msg string, buffer *bytes.Buffer) { args = append(args, string(buffer.Bytes()[1:])) } l.t.Log(args...) + + l.buffer.mutex.Lock() + defer l.buffer.mutex.Unlock() + + // Store as text. + l.buffer.text.WriteString(string(what)) + for i := 1; i < len(args); i++ { + l.buffer.text.WriteByte(' ') + l.buffer.text.WriteString(args[i].(string)) + } + lastArg := args[len(args)-1].(string) + if lastArg[len(lastArg)-1] != '\n' { + l.buffer.text.WriteByte('\n') + } + + // Store as raw data. + l.buffer.log = append(l.buffer.log, + LogEntry{ + Timestamp: time.Now(), + Type: what, + Prefix: l.prefix, + Message: msg, + Verbosity: level, + Err: err, + KVList: append(l.values, kvList...), + }, + ) } // WithName returns a new logr.Logger with the specified name appended. klogr @@ -133,5 +319,14 @@ func (l *tlogger) WithValues(kvList ...interface{}) logr.LogSink { return &new } +func (l *tlogger) GetUnderlying() TL { + return l.t +} + +func (l *tlogger) GetBuffer() Buffer { + return l.buffer +} + var _ logr.LogSink = &tlogger{} var _ logr.CallStackHelperLogSink = &tlogger{} +var _ Underlier = &tlogger{}