diff --git a/klog.go b/klog.go index 1bd1c2e98..ceb921a1a 100644 --- a/klog.go +++ b/klog.go @@ -812,14 +812,17 @@ func (l *loggingT) output(s severity, log logr.InfoLogger, buf *buffer, file str } } data := buf.Bytes() - if log != nil { - // TODO: set 'severity' and caller information as structured log info - // keysAndValues := []interface{}{"severity", severityName[s], "file", file, "line", line} + // In later version, we should check argument s is either errorLog or infoLog. + // However for now, as backward compatibility, all s other than errorLog goes to l.logr.Info(). + // if l.logr != nil && (s == errorLog || s == infoLog) { + if l.logr != nil { if s == errorLog { - l.logr.Error(nil, string(data)) + l.logr.Error(nil, string(data), "severity", severityName[s], "file", file, "line", line) } else { - log.Info(string(data)) + l.logr.Info(string(data), "severity", severityName[s], "file", file, "line", line) } + } else if log != nil && s == infoLog { + log.Info(string(data), "severity", severityName[s], "file", file, "line", line) } else if l.toStderr { os.Stderr.Write(data) } else { diff --git a/klog_test.go b/klog_test.go index fc1fdfd8a..7f3b2dc93 100644 --- a/klog_test.go +++ b/klog_test.go @@ -20,6 +20,7 @@ import ( "bytes" "flag" "fmt" + "github.com/go-logr/logr" "io/ioutil" stdLog "log" "os" @@ -639,3 +640,300 @@ func TestInitFlags(t *testing.T) { t.Fatal("Expected log_file_max_size to be 2048") } } + +func createTestValueOfLoggingT() *loggingT { + l := new(loggingT) + l.toStderr = true + l.alsoToStderr = false + l.stderrThreshold = errorLog + l.verbosity = Level(0) + l.skipHeaders = false + l.skipLogHeaders = false + l.addDirHeader = false + return l +} + +// testInfoLogger implements logr.infoLogger. +var _ logr.InfoLogger = testInfoLogger{} + +// testInfoLogger doesn't write log to any place. +// testInfoLogger.Info() only stores values passed as argument +// to another value of type testInfoLogger. +type testInfoLogger struct { + verbosity int + message string + keysAndValues []interface{} + enabled bool + + store *testInfoLogger +} + +func (il testInfoLogger) Info(msg string, kvs ...interface{}) { + il.store.message = msg + il.store.keysAndValues = append(il.keysAndValues, kvs...) +} + +func (il testInfoLogger) Enabled() bool { + return il.enabled +} + +// testLogger implements logr.Logger. +var _ logr.Logger = testLogger{} + +// testLogger doesn't write log to any place. +// testLogger.Info() & testLogger.Error() only store values passed as argument +// to another value of type testLogger. +type testLogger struct { + name []string + verbosity int // verbosity of logr.Logger should be 0. + err error + message string + keysAndValues []interface{} + enabled bool + + store *testLogger +} + +func (l testLogger) Info(msg string, kvs ...interface{}) { + l.store.message = msg + l.store.keysAndValues = append(l.keysAndValues, kvs...) +} + +func (l testLogger) Enabled() bool { + return l.enabled +} + +func (l testLogger) Error(err error, msg string, kvs ...interface{}) { + l.store.err = err + l.store.message = msg + l.store.keysAndValues = append(l.keysAndValues, kvs...) +} + +func (l testLogger) V(level int) logr.InfoLogger { + ril := testInfoLogger{} + ril.verbosity = level + ril.message = l.message + ril.keysAndValues = l.keysAndValues + ril.enabled = true + return ril +} + +func (l testLogger) WithValues(kvs ...interface{}) logr.Logger { + rl := l + rl.keysAndValues = append(rl.keysAndValues, kvs...) + return rl +} + +func (l testLogger) WithName(name string) logr.Logger { + rl := l + rl.name = append(rl.name, name) + return rl +} + +func compareKeysAndValues(a, b []interface{}) bool { + if len(a) != len(b) { + return false + } + + for i := 0; i < len(a); i++ { + if a[i] != b[i] { + return false + } + } + + return true +} + +/* +output method of loggingT is called at + * println method of loggingT + * printDepth method of loggingT + * printf method of loggingT + * printWithFileLine method of loggingT + * print method of loggingT (This method calls printDepth. So indirectly call output.) + +And above methods are called at + * Write method of logBridge + * Info method of Verbose + * Infoln method of Verbose + * Infof method of Verbose + * Info function + * InfoDepth function + * Infoln function + * Infof function + * Warning function + * WarningDepth function + * Warningln function + * Warningf function + * Error function + * ErrorDepth function + * Errorln function + * Errorf function + * Fatal function + * FatalDepth function + * Fatalln function + * Fatalf function + * Exit function + * ExitDepth function + * Exitln function + * Exitf function +and + * receiver of output method is global variable logging in all these methods + * argument log of output method is + 1. Verbose.logr at Info, Infoln and Infof method of Verbose with argument s as infoLog, or + 2. global variable logging at all other these methods with argument s as any severity. + +So currently, there should be 4 situations in which logr.InfoLogger/logr.Logger is handled: + * (Situation 1) log argument is set with severity as infoLog & logr field of receiver l is set + => Info method of l.logr is called. + * (Situation 2) log argument is set with severity as infoLog & logr field of receiver l is not set + => Info method of log argument (type logr.InfoLogger) is called. + * (Situation 3) logr field of receiver l is set & l.logr is passed as log argument with severity as any value + => * [Situation 3-1] If severity is errorLog, Error method of l.logr is called + * [Situation 3-2] If severity is not infoLog, Info method of l.logr is called + +This test function checks whether above 4 situations hold by runing sub-tests. +*/ +func TestOutput(t *testing.T) { + // Situation 1 + t.Run("Situation 1", func(t *testing.T) { + kv1 := []interface{}{ + "severity", severityName[infoLog], + "file", "keyValue1", + "line", 1, + } + + msg1 := "situation1" + + bf1 := &buffer{} + bf1.next = nil + bf1.Reset() + // Call fmt.Fprintln() to emulate output method is called by println method of loggingT. + fmt.Fprintln(bf1, msg1) + + // Value of type *testLogger to which test is run + tl1 := new(testLogger) + + // Value of type loggingT which call output method + l1 := createTestValueOfLoggingT() + l1.logr = testLogger{store: tl1} + + // Want value of testLogger + wantLogger1 := testLogger{} + // Because we call fmt.Fprintln() above to emulate println method, add "\n" + wantLogger1.message = msg1 + "\n" + wantLogger1.keysAndValues = kv1 + + l1.output(infoLog, l1.logr, bf1, "keyValue1", 1, false) + + if tl1.message != wantLogger1.message || !compareKeysAndValues(tl1.keysAndValues, wantLogger1.keysAndValues) { + t.Errorf("output method of loggingT doesn't call logr.Logger.Info correctly:\nwant:\n\tmessage:\t%v\n\tkeysAndValues:\t%v\ngot:\n\tmessage:\t%v\n\tkeysAndValues:\t%v\n", wantLogger1.message, wantLogger1.keysAndValues, tl1.message, tl1.keysAndValues) + } + }) + + // Situation 2 + t.Run("Situation 2", func(t *testing.T) { + kv2 := []interface{}{ + "severity", severityName[infoLog], + "file", "keyValue2", + "line", 2, + } + + msg2 := "situation2" + + bf2 := &buffer{} + bf2.next = nil + bf2.Reset() + // Call fmt.Fprintln() to emulate output method is called by println method of loggingT. + fmt.Fprintln(bf2, msg2) + + // Value of type *testLogger to which test is run + tl2 := new(testLogger) + + // Value of type loggingT which call output method & logr filed is not set (empty) + el2 := createTestValueOfLoggingT() + + l2 := createTestValueOfLoggingT() + l2.logr = testLogger{store: tl2} + + // Want value of testLogger + wantLogger2 := testLogger{} + // Because we call fmt.Fprintln() above to emulate println method, add "\n" + wantLogger2.message = msg2 + "\n" + wantLogger2.keysAndValues = kv2 + + el2.output(infoLog, l2.logr, bf2, "keyValue2", 2, false) + + if tl2.message != wantLogger2.message || !compareKeysAndValues(tl2.keysAndValues, wantLogger2.keysAndValues) { + t.Errorf("output method of loggingT doesn't call logr.Logger.Info correctly:\nwant:\n\tmessage:\t%v\n\tkeysAndValues:\t%v\ngot:\n\tmessage:\t%v\n\tkeysAndValues:\t%v\n", wantLogger2.message, wantLogger2.keysAndValues, tl2.message, tl2.keysAndValues) + } + }) + + // Situation 3-1 & 3-2 + // Currently, in output method, logr.Logger.Error(err error, msg string, keysAndValues ...interface{}) + // is called with nil as err argument. So we don't check whether value passed as err is correctly set. + testCases := []struct { + subt string + kv []interface{} + msg string + severity severity + file string + line int + }{ + { + subt: "Situation 3-1", + kv: []interface{}{ + "severity", severityName[errorLog], + "file", "keyValue31", + "line", 31, + }, + msg: "situation31", + severity: errorLog, + file: "keyValue31", + line: 31, + }, + { + subt: "Situation 3-2", + kv: []interface{}{ + "severity", severityName[warningLog], + "file", "keyValue32", + "line", 32, + }, + msg: "situation32", + severity: warningLog, + file: "keyValue32", + line: 32, + }, + } + + for _, tv := range testCases { + t.Run(tv.subt, func(t *testing.T) { + + bf3 := &buffer{} + bf3.next = nil + bf3.Reset() + // Call fmt.Fprintln() to emulate output method is called by println method of loggingT. + fmt.Fprintln(bf3, tv.msg) + + // Value of type *testLogger to which test is run + tl3 := new(testLogger) + + // Value of type loggingT which call output method + l3 := createTestValueOfLoggingT() + l3.logr = testLogger{store: tl3} + + // Want value of testLogger + wantLogger3 := testLogger{} + // Because we call fmt.Fprintln() above to emulate println method, add "\n" + wantLogger3.message = tv.msg + "\n" + wantLogger3.keysAndValues = tv.kv + + l3.output(tv.severity, l3.logr, bf3, tv.file, tv.line, false) + + if tl3.message != wantLogger3.message || !compareKeysAndValues(tl3.keysAndValues, wantLogger3.keysAndValues) { + t.Errorf("output method of loggingT doesn't call logr.Logger.Info correctly:\nwant:\n\tmessage:\t%v\n\tkeysAndValues:\t%v\ngot:\n\tmessage:\t%v\n\tkeysAndValues:\t%v\n", wantLogger3.message, wantLogger3.keysAndValues, tl3.message, tl3.keysAndValues) + } + }) + } + +}