diff --git a/grpclog/internal/loggerv2.go b/grpclog/internal/loggerv2.go index 07df71e98a87..ed90060c3cba 100644 --- a/grpclog/internal/loggerv2.go +++ b/grpclog/internal/loggerv2.go @@ -101,6 +101,22 @@ var severityName = []string{ fatalLog: "FATAL", } +// sprintf is fmt.Sprintf. +// These vars exist to make it possible to test that expensive format calls aren't made unnecessarily. +var sprintf = fmt.Sprintf + +// sprint is fmt.Sprint. +// These vars exist to make it possible to test that expensive format calls aren't made unnecessarily. +var sprint = fmt.Sprint + +// sprintln is fmt.Sprintln. +// These vars exist to make it possible to test that expensive format calls aren't made unnecessarily. +var sprintln = fmt.Sprintln + +// exit is os.Exit. +// This var exists to make it possible to test functions calling os.Exit. +var exit = os.Exit + // loggerT is the default logger used by grpclog. type loggerT struct { m []*log.Logger @@ -111,7 +127,7 @@ type loggerT struct { func (g *loggerT) output(severity int, s string) { sevStr := severityName[severity] if !g.jsonFormat { - g.m[severity].Output(2, fmt.Sprintf("%v: %v", sevStr, s)) + g.m[severity].Output(2, sevStr+": "+s) return } // TODO: we can also include the logging component, but that needs more @@ -123,55 +139,79 @@ func (g *loggerT) output(severity int, s string) { g.m[severity].Output(2, string(b)) } +func (g *loggerT) printf(severity int, format string, args ...any) { + // Note the discard check is duplicated in each print func, rather than in + // output, to avoid the expensive Sprint calls. + // De-duplicating this by moving to output would be a significant performance regression! + if lg := g.m[severity]; lg.Writer() == io.Discard { + return + } + g.output(severity, sprintf(format, args...)) +} + +func (g *loggerT) print(severity int, v ...any) { + if lg := g.m[severity]; lg.Writer() == io.Discard { + return + } + g.output(severity, sprint(v...)) +} + +func (g *loggerT) println(severity int, v ...any) { + if lg := g.m[severity]; lg.Writer() == io.Discard { + return + } + g.output(severity, sprintln(v...)) +} + func (g *loggerT) Info(args ...any) { - g.output(infoLog, fmt.Sprint(args...)) + g.print(infoLog, args...) } func (g *loggerT) Infoln(args ...any) { - g.output(infoLog, fmt.Sprintln(args...)) + g.println(infoLog, args...) } func (g *loggerT) Infof(format string, args ...any) { - g.output(infoLog, fmt.Sprintf(format, args...)) + g.printf(infoLog, format, args...) } func (g *loggerT) Warning(args ...any) { - g.output(warningLog, fmt.Sprint(args...)) + g.print(warningLog, args...) } func (g *loggerT) Warningln(args ...any) { - g.output(warningLog, fmt.Sprintln(args...)) + g.println(warningLog, args...) } func (g *loggerT) Warningf(format string, args ...any) { - g.output(warningLog, fmt.Sprintf(format, args...)) + g.printf(warningLog, format, args...) } func (g *loggerT) Error(args ...any) { - g.output(errorLog, fmt.Sprint(args...)) + g.print(errorLog, args...) } func (g *loggerT) Errorln(args ...any) { - g.output(errorLog, fmt.Sprintln(args...)) + g.println(errorLog, args...) } func (g *loggerT) Errorf(format string, args ...any) { - g.output(errorLog, fmt.Sprintf(format, args...)) + g.printf(errorLog, format, args...) } func (g *loggerT) Fatal(args ...any) { - g.output(fatalLog, fmt.Sprint(args...)) - os.Exit(1) + g.print(fatalLog, args...) + exit(1) } func (g *loggerT) Fatalln(args ...any) { - g.output(fatalLog, fmt.Sprintln(args...)) - os.Exit(1) + g.println(fatalLog, args...) + exit(1) } func (g *loggerT) Fatalf(format string, args ...any) { - g.output(fatalLog, fmt.Sprintf(format, args...)) - os.Exit(1) + g.printf(fatalLog, format, args...) + exit(1) } func (g *loggerT) V(l int) bool { @@ -186,19 +226,42 @@ type LoggerV2Config struct { FormatJSON bool } +// combineLoggers returns a combined logger for both higher & lower severity logs, +// or only one if the other is io.Discard. +// +// This uses io.Discard instead of io.MultiWriter when all loggers +// are set to io.Discard. Both this package and the standard log package have +// significant optimizations for io.Discard, which io.MultiWriter lacks (as of +// this writing). +func combineLoggers(lower, higher io.Writer) io.Writer { + if lower == io.Discard { + return higher + } + if higher == io.Discard { + return lower + } + return io.MultiWriter(lower, higher) +} + // NewLoggerV2 creates a new LoggerV2 instance with the provided configuration. // The infoW, warningW, and errorW writers are used to write log messages of // different severity levels. func NewLoggerV2(infoW, warningW, errorW io.Writer, c LoggerV2Config) LoggerV2 { - var m []*log.Logger flag := log.LstdFlags if c.FormatJSON { flag = 0 } - m = append(m, log.New(infoW, "", flag)) - m = append(m, log.New(io.MultiWriter(infoW, warningW), "", flag)) - ew := io.MultiWriter(infoW, warningW, errorW) // ew will be used for error and fatal. - m = append(m, log.New(ew, "", flag)) - m = append(m, log.New(ew, "", flag)) + + warningW = combineLoggers(infoW, warningW) + errorW = combineLoggers(errorW, warningW) + + fatalW := errorW + + m := []*log.Logger{ + log.New(infoW, "", flag), + log.New(warningW, "", flag), + log.New(errorW, "", flag), + log.New(fatalW, "", flag), + } return &loggerT{m: m, v: c.Verbosity, jsonFormat: c.FormatJSON} } diff --git a/grpclog/internal/loggerv2_test.go b/grpclog/internal/loggerv2_test.go index b22ecbde82a0..3369448bef5f 100644 --- a/grpclog/internal/loggerv2_test.go +++ b/grpclog/internal/loggerv2_test.go @@ -20,11 +20,86 @@ package internal import ( "bytes" + "encoding/json" "fmt" + "io" + "os" + "reflect" "regexp" + "strings" "testing" ) +// logFuncStr is a string used via testCheckLogContainsFuncStr to test the +// logger output. +const logFuncStr = "called-func" + +func makeSprintfErr(t *testing.T) func(format string, a ...any) string { + return func(string, ...any) string { + t.Errorf("got: sprintf called on io.Discard logger, want: expensive sprintf to not be called for io.Discard") + return "" + } +} + +func makeSprintErr(t *testing.T) func(a ...any) string { + return func(...any) string { + t.Errorf("got: sprint called on io.Discard logger, want: expensive sprint to not be called for io.Discard") + return "" + } +} + +// checkLogContainsFuncStr checks that the logger buffer logBuf contains +// logFuncStr. +func checkLogContainsFuncStr(t *testing.T, logBuf []byte) { + if !bytes.Contains(logBuf, []byte(logFuncStr)) { + t.Errorf("got '%v', want logger func to be called and print '%v'", string(logBuf), logFuncStr) + } +} + +// checkBufferWasWrittenAsExpected checks that the log buffer buf was written as expected, +// per the discard, logTYpe, msg, and isJSON arguments. +func checkBufferWasWrittenAsExpected(t *testing.T, buf *bytes.Buffer, discard bool, logType string, msg string, isJSON bool) { + bts, err := buf.ReadBytes('\n') + if discard { + if err == nil { + t.Fatalf("got '%v', want discard %v to not write", string(bts), logType) + } else if err != io.EOF { + t.Fatalf("got '%v', want discard %v buffer to be EOF", err, logType) + } + } else { + if err != nil { + t.Fatalf("got '%v', want non-discard %v to not error", err, logType) + } else if !bytes.Contains(bts, []byte(msg)) { + t.Fatalf("got '%v', want non-discard %v buffer contain message '%v'", string(bts), logType, msg) + } + if isJSON { + obj := map[string]string{} + if err := json.Unmarshal(bts, &obj); err != nil { + t.Fatalf("got '%v', want non-discard json %v to unmarshal", err, logType) + } else if _, ok := obj["severity"]; !ok { + t.Fatalf("got '%v', want non-discard json %v to have severity field", "missing severity", logType) + + } else if jsonMsg, ok := obj["message"]; !ok { + t.Fatalf("got '%v', want non-discard json %v to have message field", "missing message", logType) + + } else if !strings.Contains(jsonMsg, msg) { + t.Fatalf("got '%v', want non-discard json %v buffer contain message '%v'", string(bts), logType, msg) + } + } + } +} + +// check if b is in the format of: +// +// 2017/04/07 14:55:42 WARNING: WARNING +func checkLogForSeverity(s int, b []byte) error { + expected := regexp.MustCompile(fmt.Sprintf(`^[0-9]{4}/[0-9]{2}/[0-9]{2} [0-9]{2}:[0-9]{2}:[0-9]{2} %s: %s\n$`, severityName[s], severityName[s])) + if m := expected.Match(b); !m { + return fmt.Errorf("got: %v, want string in format of: %v", string(b), severityName[s]+": 2016/10/05 17:09:26 "+severityName[s]) + } + return nil +} + func TestLoggerV2Severity(t *testing.T) { buffers := []*bytes.Buffer{new(bytes.Buffer), new(bytes.Buffer), new(bytes.Buffer)} l := NewLoggerV2(buffers[infoLog], buffers[warningLog], buffers[errorLog], LoggerV2Config{}) @@ -42,7 +117,7 @@ func TestLoggerV2Severity(t *testing.T) { for j := i; j < fatalLog; j++ { b, err := buf.ReadBytes('\n') if err != nil { - t.Fatal(err) + t.Fatalf("level %d: %v", j, err) } if err := checkLogForSeverity(j, b); err != nil { t.Fatal(err) @@ -51,13 +126,225 @@ func TestLoggerV2Severity(t *testing.T) { } } -// check if b is in the format of: -// -// 2017/04/07 14:55:42 WARNING: WARNING -func checkLogForSeverity(s int, b []byte) error { - expected := regexp.MustCompile(fmt.Sprintf(`^[0-9]{4}/[0-9]{2}/[0-9]{2} [0-9]{2}:[0-9]{2}:[0-9]{2} %s: %s\n$`, severityName[s], severityName[s])) - if m := expected.Match(b); !m { - return fmt.Errorf("got: %v, want string in format of: %v", string(b), severityName[s]+": 2016/10/05 17:09:26 "+severityName[s]) +// TestLoggerV2PrintFuncDiscardOnlyInfo ensures that logs at the INFO level are +// discarded when set to io.Discard, while logs at other levels (WARN, ERROR) +// are still printed. It does this by using a custom error function that raises +// an error if the logger attempts to print at the INFO level, ensuring early +// return when io.Discard is used. +func TestLoggerV2PrintFuncDiscardOnlyInfo(t *testing.T) { + buffers := []*bytes.Buffer{nil, new(bytes.Buffer), new(bytes.Buffer)} + logger := NewLoggerV2(io.Discard, buffers[warningLog], buffers[errorLog], LoggerV2Config{}) + loggerTp := logger.(*loggerT) + + // test that output doesn't call expensive printf funcs on an io.Discard logger + sprintf = makeSprintfErr(t) + sprint = makeSprintErr(t) + sprintln = makeSprintErr(t) + + loggerTp.output(infoLog, "something") + + sprintf = fmt.Sprintf + sprint = fmt.Sprint + sprintln = fmt.Sprintln + + loggerTp.output(errorLog, logFuncStr) + warnB, err := buffers[warningLog].ReadBytes('\n') + if err != nil { + t.Fatalf("level %v: %v", warningLog, err) + } + checkLogContainsFuncStr(t, warnB) + + errB, err := buffers[errorLog].ReadBytes('\n') + if err != nil { + t.Fatalf("level %v: %v", errorLog, err) + } + checkLogContainsFuncStr(t, errB) +} + +func TestLoggerV2PrintFuncNoDiscard(t *testing.T) { + buffers := []*bytes.Buffer{new(bytes.Buffer), new(bytes.Buffer), new(bytes.Buffer)} + logger := NewLoggerV2(buffers[infoLog], buffers[warningLog], buffers[errorLog], LoggerV2Config{}) + loggerTp := logger.(*loggerT) + + loggerTp.output(errorLog, logFuncStr) + + infoB, err := buffers[infoLog].ReadBytes('\n') + if err != nil { + t.Fatalf("level %v: %v", infoLog, err) + } + checkLogContainsFuncStr(t, infoB) + + warnB, err := buffers[warningLog].ReadBytes('\n') + if err != nil { + t.Fatalf("level %v: %v", warningLog, err) + } + checkLogContainsFuncStr(t, warnB) + + errB, err := buffers[errorLog].ReadBytes('\n') + if err != nil { + t.Fatalf("level %v: %v", errorLog, err) + } + checkLogContainsFuncStr(t, errB) +} + +// TestLoggerV2PrintFuncAllDiscard tests that discard loggers don't log. +func TestLoggerV2PrintFuncAllDiscard(t *testing.T) { + logger := NewLoggerV2(io.Discard, io.Discard, io.Discard, LoggerV2Config{}) + loggerTp := logger.(*loggerT) + + sprintf = makeSprintfErr(t) + sprint = makeSprintErr(t) + sprintln = makeSprintErr(t) + + // test that printFunc doesn't call the log func on discard loggers + // makeLogFuncErr will fail the test if it's called + loggerTp.output(infoLog, logFuncStr) + loggerTp.output(warningLog, logFuncStr) + loggerTp.output(errorLog, logFuncStr) + + sprintf = fmt.Sprintf + sprint = fmt.Sprint + sprintln = fmt.Sprintln +} + +func TestLoggerV2PrintFuncAllCombinations(t *testing.T) { + const ( + print int = iota + printf + println + ) + + type testDiscard struct { + discardInf bool + discardWarn bool + discardErr bool + + printType int + formatJSON bool + } + + discardName := func(td testDiscard) string { + strs := []string{} + if td.discardInf { + strs = append(strs, "discardInfo") + } + if td.discardWarn { + strs = append(strs, "discardWarn") + } + if td.discardErr { + strs = append(strs, "discardErr") + } + if len(strs) == 0 { + strs = append(strs, "noDiscard") + } + return strings.Join(strs, " ") + } + var printName = []string{ + print: "print", + printf: "printf", + println: "println", + } + var jsonName = map[bool]string{ + true: "json", + false: "noJson", + } + + discardTests := []testDiscard{} + for _, di := range []bool{true, false} { + for _, dw := range []bool{true, false} { + for _, de := range []bool{true, false} { + for _, pt := range []int{print, printf, println} { + for _, fj := range []bool{true, false} { + discardTests = append(discardTests, testDiscard{discardInf: di, discardWarn: dw, discardErr: de, printType: pt, formatJSON: fj}) + } + } + } + } + } + + for _, discardTest := range discardTests { + testName := fmt.Sprintf("%v %v %v", jsonName[discardTest.formatJSON], printName[discardTest.printType], discardName(discardTest)) + t.Run(testName, func(t *testing.T) { + cfg := LoggerV2Config{FormatJSON: discardTest.formatJSON} + + buffers := []*bytes.Buffer{new(bytes.Buffer), new(bytes.Buffer), new(bytes.Buffer)} + writers := []io.Writer{buffers[infoLog], buffers[warningLog], buffers[errorLog]} + if discardTest.discardInf { + writers[infoLog] = io.Discard + } + if discardTest.discardWarn { + writers[warningLog] = io.Discard + } + if discardTest.discardErr { + writers[errorLog] = io.Discard + } + logger := NewLoggerV2(writers[infoLog], writers[warningLog], writers[errorLog], cfg) + + msgInf := "someinfo" + msgWarn := "somewarn" + msgErr := "someerr" + if discardTest.printType == print { + logger.Info(msgInf) + logger.Warning(msgWarn) + logger.Error(msgErr) + } else if discardTest.printType == printf { + logger.Infof("%v", msgInf) + logger.Warningf("%v", msgWarn) + logger.Errorf("%v", msgErr) + } else if discardTest.printType == println { + logger.Infoln(msgInf) + logger.Warningln(msgWarn) + logger.Errorln(msgErr) + } + + // verify the test Discard, log type, message, and json arguments were logged as-expected + + checkBufferWasWrittenAsExpected(t, buffers[infoLog], discardTest.discardInf, "info", msgInf, cfg.FormatJSON) + checkBufferWasWrittenAsExpected(t, buffers[warningLog], discardTest.discardWarn, "warning", msgWarn, cfg.FormatJSON) + checkBufferWasWrittenAsExpected(t, buffers[errorLog], discardTest.discardErr, "error", msgErr, cfg.FormatJSON) + }) + } +} + +func TestLoggerV2Fatal(t *testing.T) { + const ( + print = "print" + println = "println" + printf = "printf" + ) + printFuncs := []string{print, println, printf} + + exitCalls := []int{} + + if reflect.ValueOf(exit).Pointer() != reflect.ValueOf(os.Exit).Pointer() { + t.Error("got: exit isn't os.Exit, want exit var to be os.Exit") + } + + exit = func(code int) { + exitCalls = append(exitCalls, code) + } + defer func() { + exit = os.Exit + }() + + for _, printFunc := range printFuncs { + buffers := []*bytes.Buffer{new(bytes.Buffer), new(bytes.Buffer), new(bytes.Buffer)} + logger := NewLoggerV2(buffers[infoLog], buffers[warningLog], buffers[errorLog], LoggerV2Config{}) + switch printFunc { + case print: + logger.Fatal("fatal") + case println: + logger.Fatalln("fatalln") + case printf: + logger.Fatalf("fatalf %d", 42) + default: + t.Errorf("unknown print type '%v'", printFunc) + } + + checkBufferWasWrittenAsExpected(t, buffers[errorLog], false, "fatal", "fatal", false) + if len(exitCalls) == 0 { + t.Error("got: no exit call, want fatal log to call exit") + } + exitCalls = []int{} } - return nil }