diff --git a/glog.go b/glog.go index dd0ed101..8c00e737 100644 --- a/glog.go +++ b/glog.go @@ -15,8 +15,26 @@ // limitations under the License. // Package glog implements logging analogous to the Google-internal C++ INFO/ERROR/V setup. -// It provides functions Info, Warning, Error, Fatal, plus formatting variants such as -// Infof. It also provides V-style logging controlled by the -v and -vmodule=file=2 flags. +// It provides functions that have a name matched by regex: +// +// (Info|Warning|Error|Fatal)(Context)?(Depth)?(f)? +// +// If Context is present, function takes context.Context argument. The +// context is used to pass through the Trace Context to log sinks that can make use +// of it. +// It is recommended to use the context variant of the functions over the non-context +// variants if a context is available to make sure the Trace Contexts are present +// in logs. +// +// If Depth is present, this function calls log from a different depth in the call stack. +// This enables a callee to emit logs that use the callsite information of its caller +// or any other callers in the stack. When depth == 0, the original callee's line +// information is emitted. When depth > 0, depth frames are skipped in the call stack +// and the final frame is treated like the original callee to Info. +// +// If 'f' is present, function formats according to a format specifier. +// +// This package also provides V-style logging controlled by the -v and -vmodule=file=2 flags. // // Basic examples: // @@ -82,6 +100,7 @@ package glog import ( "bytes" + "context" "errors" "fmt" stdLog "log" @@ -182,9 +201,14 @@ func appendBacktrace(depth int, format string, args []any) (string, []any) { return format, args } -// logf writes a log message for a log function call (or log function wrapper) -// at the given depth in the current goroutine's stack. +// logf acts as ctxlogf, but doesn't expect a context. func logf(depth int, severity logsink.Severity, verbose bool, stack stack, format string, args ...any) { + ctxlogf(nil, depth+1, severity, verbose, stack, format, args...) +} + +// ctxlogf writes a log message for a log function call (or log function wrapper) +// at the given depth in the current goroutine's stack. +func ctxlogf(ctx context.Context, depth int, severity logsink.Severity, verbose bool, stack stack, format string, args ...any) { now := timeNow() _, file, line, ok := runtime.Caller(depth + 1) if !ok { @@ -198,6 +222,7 @@ func logf(depth int, severity logsink.Severity, verbose bool, stack stack, forma metai, meta := metaPoolGet() *meta = logsink.Meta{ + Context: ctx, Time: now, File: file, Line: line, @@ -207,6 +232,9 @@ func logf(depth int, severity logsink.Severity, verbose bool, stack stack, forma Thread: int64(pid), } sinkf(meta, format, args...) + // Clear pointer fields so they can be garbage collected early. + meta.Context = nil + meta.Stack = nil metaPool.Put(metai) } @@ -418,6 +446,36 @@ func (v Verbose) Infof(format string, args ...any) { } } +// InfoContext is equivalent to the global InfoContext function, guarded by the value of v. +// See the documentation of V for usage. +func (v Verbose) InfoContext(ctx context.Context, args ...any) { + v.InfoContextDepth(ctx, 1, args...) +} + +// InfoContextf is equivalent to the global InfoContextf function, guarded by the value of v. +// See the documentation of V for usage. +func (v Verbose) InfoContextf(ctx context.Context, format string, args ...any) { + if v { + ctxlogf(ctx, 1, logsink.Info, true, noStack, format, args...) + } +} + +// InfoContextDepth is equivalent to the global InfoContextDepth function, guarded by the value of v. +// See the documentation of V for usage. +func (v Verbose) InfoContextDepth(ctx context.Context, depth int, args ...any) { + if v { + ctxlogf(ctx, depth+1, logsink.Info, true, noStack, defaultFormat(args), args...) + } +} + +// InfoContextDepthf is equivalent to the global InfoContextDepthf function, guarded by the value of v. +// See the documentation of V for usage. +func (v Verbose) InfoContextDepthf(ctx context.Context, depth int, format string, args ...any) { + if v { + ctxlogf(ctx, depth+1, logsink.Info, true, noStack, format, args...) + } +} + // Info logs to the INFO log. // Arguments are handled in the manner of fmt.Print; a newline is appended if missing. func Info(args ...any) { @@ -450,6 +508,30 @@ func Infof(format string, args ...any) { logf(1, logsink.Info, false, noStack, format, args...) } +// InfoContext is like [Info], but with an extra [context.Context] parameter. The +// context is used to pass the Trace Context to log sinks. +func InfoContext(ctx context.Context, args ...any) { + InfoContextDepth(ctx, 1, args...) +} + +// InfoContextf is like [Infof], but with an extra [context.Context] parameter. The +// context is used to pass the Trace Context to log sinks. +func InfoContextf(ctx context.Context, format string, args ...any) { + ctxlogf(ctx, 1, logsink.Info, false, noStack, format, args...) +} + +// InfoContextDepth is like [InfoDepth], but with an extra [context.Context] parameter. The +// context is used to pass the Trace Context to log sinks. +func InfoContextDepth(ctx context.Context, depth int, args ...any) { + ctxlogf(ctx, depth+1, logsink.Info, false, noStack, defaultFormat(args), args...) +} + +// InfoContextDepthf is like [InfoDepthf], but with an extra [context.Context] parameter. The +// context is used to pass the Trace Context to log sinks. +func InfoContextDepthf(ctx context.Context, depth int, format string, args ...any) { + ctxlogf(ctx, depth+1, logsink.Info, false, noStack, format, args...) +} + // Warning logs to the WARNING and INFO logs. // Arguments are handled in the manner of fmt.Print; a newline is appended if missing. func Warning(args ...any) { @@ -480,6 +562,30 @@ func Warningf(format string, args ...any) { logf(1, logsink.Warning, false, noStack, format, args...) } +// WarningContext is like [Warning], but with an extra [context.Context] parameter. The +// context is used to pass the Trace Context to log sinks. +func WarningContext(ctx context.Context, args ...any) { + WarningContextDepth(ctx, 1, args...) +} + +// WarningContextf is like [Warningf], but with an extra [context.Context] parameter. The +// context is used to pass the Trace Context to log sinks. +func WarningContextf(ctx context.Context, format string, args ...any) { + ctxlogf(ctx, 1, logsink.Warning, false, noStack, format, args...) +} + +// WarningContextDepth is like [WarningDepth], but with an extra [context.Context] parameter. The +// context is used to pass the Trace Context to log sinks. +func WarningContextDepth(ctx context.Context, depth int, args ...any) { + ctxlogf(ctx, depth+1, logsink.Warning, false, noStack, defaultFormat(args), args...) +} + +// WarningContextDepthf is like [WarningDepthf], but with an extra [context.Context] parameter. The +// context is used to pass the Trace Context to log sinks. +func WarningContextDepthf(ctx context.Context, depth int, format string, args ...any) { + ctxlogf(ctx, depth+1, logsink.Warning, false, noStack, format, args...) +} + // Error logs to the ERROR, WARNING, and INFO logs. // Arguments are handled in the manner of fmt.Print; a newline is appended if missing. func Error(args ...any) { @@ -510,8 +616,32 @@ func Errorf(format string, args ...any) { logf(1, logsink.Error, false, noStack, format, args...) } -func fatalf(depth int, format string, args ...any) { - logf(depth+1, logsink.Fatal, false, withStack, format, args...) +// ErrorContext is like [Error], but with an extra [context.Context] parameter. The +// context is used to pass the Trace Context to log sinks. +func ErrorContext(ctx context.Context, args ...any) { + ErrorContextDepth(ctx, 1, args...) +} + +// ErrorContextf is like [Errorf], but with an extra [context.Context] parameter. The +// context is used to pass the Trace Context to log sinks. +func ErrorContextf(ctx context.Context, format string, args ...any) { + ctxlogf(ctx, 1, logsink.Error, false, noStack, format, args...) +} + +// ErrorContextDepth is like [ErrorDepth], but with an extra [context.Context] parameter. The +// context is used to pass the Trace Context to log sinks. +func ErrorContextDepth(ctx context.Context, depth int, args ...any) { + ctxlogf(ctx, depth+1, logsink.Error, false, noStack, defaultFormat(args), args...) +} + +// ErrorContextDepthf is like [ErrorDepthf], but with an extra [context.Context] parameter. The +// context is used to pass the Trace Context to log sinks. +func ErrorContextDepthf(ctx context.Context, depth int, format string, args ...any) { + ctxlogf(ctx, depth+1, logsink.Error, false, noStack, format, args...) +} + +func ctxfatalf(ctx context.Context, depth int, format string, args ...any) { + ctxlogf(ctx, depth+1, logsink.Fatal, false, withStack, format, args...) sinks.file.Flush() err := abortProcess() // Should not return. @@ -523,6 +653,10 @@ func fatalf(depth int, format string, args ...any) { os.Exit(2) // Exit with the same code as the default SIGABRT handler. } +func fatalf(depth int, format string, args ...any) { + ctxfatalf(nil, depth+1, format, args...) +} + // Fatal logs to the FATAL, ERROR, WARNING, and INFO logs, // including a stack trace of all running goroutines, then calls os.Exit(2). // Arguments are handled in the manner of fmt.Print; a newline is appended if missing. @@ -556,12 +690,39 @@ func Fatalf(format string, args ...any) { fatalf(1, format, args...) } -func exitf(depth int, format string, args ...any) { - logf(depth+1, logsink.Fatal, false, noStack, format, args...) +// FatalContext is like [Fatal], but with an extra [context.Context] parameter. The +// context is used to pass the Trace Context to log sinks. +func FatalContext(ctx context.Context, args ...any) { + FatalContextDepth(ctx, 1, args...) +} + +// FatalContextf is like [Fatalf], but with an extra [context.Context] parameter. The +// context is used to pass the Trace Context to log sinks. +func FatalContextf(ctx context.Context, format string, args ...any) { + ctxfatalf(ctx, 1, format, args...) +} + +// FatalContextDepth is like [FatalDepth], but with an extra [context.Context] parameter. The +// context is used to pass the Trace Context to log sinks. +func FatalContextDepth(ctx context.Context, depth int, args ...any) { + ctxfatalf(ctx, depth+1, defaultFormat(args), args...) +} + +// FatalContextDepthf is like [FatalDepthf], but with an extra [context.Context] parameter. +func FatalContextDepthf(ctx context.Context, depth int, format string, args ...any) { + ctxfatalf(ctx, depth+1, format, args...) +} + +func ctxexitf(ctx context.Context, depth int, format string, args ...any) { + ctxlogf(ctx, depth+1, logsink.Fatal, false, noStack, format, args...) sinks.file.Flush() os.Exit(1) } +func exitf(depth int, format string, args ...any) { + ctxexitf(nil, depth+1, format, args...) +} + // Exit logs to the FATAL, ERROR, WARNING, and INFO logs, then calls os.Exit(1). // Arguments are handled in the manner of fmt.Print; a newline is appended if missing. func Exit(args ...any) { @@ -590,3 +751,27 @@ func Exitln(args ...any) { func Exitf(format string, args ...any) { exitf(1, format, args...) } + +// ExitContext is like [Exit], but with an extra [context.Context] parameter. The +// context is used to pass the Trace Context to log sinks. +func ExitContext(ctx context.Context, args ...any) { + ExitContextDepth(ctx, 1, args...) +} + +// ExitContextf is like [Exitf], but with an extra [context.Context] parameter. The +// context is used to pass the Trace Context to log sinks. +func ExitContextf(ctx context.Context, format string, args ...any) { + ctxexitf(ctx, 1, format, args...) +} + +// ExitContextDepth is like [ExitDepth], but with an extra [context.Context] parameter. The +// context is used to pass the Trace Context to log sinks. +func ExitContextDepth(ctx context.Context, depth int, args ...any) { + ctxexitf(ctx, depth+1, defaultFormat(args), args...) +} + +// ExitContextDepthf is like [ExitDepthf], but with an extra [context.Context] parameter. The +// context is used to pass the Trace Context to log sinks. +func ExitContextDepthf(ctx context.Context, depth int, format string, args ...any) { + ctxexitf(ctx, depth+1, format, args...) +} diff --git a/glog_context_test.go b/glog_context_test.go new file mode 100644 index 00000000..9dbac834 --- /dev/null +++ b/glog_context_test.go @@ -0,0 +1,62 @@ +package glog + +import ( + "context" + "flag" + "testing" + + "github.com/golang/glog/internal/logsink" +) + +type contextKey string +type fakeLogSink struct { + context context.Context +} + +var ctxKey = contextKey("key") +var ctxValue = "some-value" +var originalSinks = logsink.StructuredSinks + +func (s *fakeLogSink) Printf(meta *logsink.Meta, format string, args ...any) (int, error) { + s.context = meta.Context + return 0, nil +} + +// Test that log.(Info|Error|Warning)Context functions behave the same as non context variants +// and pass right context. +func TestLogContext(t *testing.T) { + fakeLogSink := &fakeLogSink{} + logsink.StructuredSinks = append([]logsink.Structured{fakeLogSink}, originalSinks...) + + funcs := map[string]func(ctx context.Context, args ...any){ + "InfoContext": InfoContext, + "InfoContextDepth": func(ctx context.Context, args ...any) { InfoContextDepth(ctx, 2, args) }, + "ErrorContext": ErrorContext, + "WarningContext": WarningContext, + } + + ctx := context.WithValue(context.Background(), ctxKey, ctxValue) + for name, f := range funcs { + f(ctx, "test") + want := ctxValue + if got := fakeLogSink.context.Value(ctxKey); got != want { + t.Errorf("%s: context value unexpectedly missing: got %q, want %q", name, got, want) + } + } +} + +// Test that V.InfoContext behaves the same as V.Info and passes right context. +func TestVInfoContext(t *testing.T) { + fakeLogSink := &fakeLogSink{} + logsink.StructuredSinks = append([]logsink.Structured{fakeLogSink}, originalSinks...) + if err := flag.Lookup("v").Value.Set("2"); err != nil { + t.Fatalf("Failed to set -v=2: %v", err) + } + defer flag.Lookup("v").Value.Set("0") + ctx := context.WithValue(context.Background(), ctxKey, ctxValue) + V(2).InfoContext(ctx, "test") + want := ctxValue + if got := fakeLogSink.context.Value(ctxKey); got != want { + t.Errorf("V.InfoContext: context value unexpectedly missing: got %q, want %q", got, want) + } +} diff --git a/glog_test.go b/glog_test.go index 81c43ce1..54762c5f 100644 --- a/glog_test.go +++ b/glog_test.go @@ -2,6 +2,7 @@ package glog import ( "bytes" + "context" "flag" "fmt" "io/ioutil" @@ -36,6 +37,7 @@ type flushBuffer struct { } func (f *flushBuffer) Flush() error { + f.Buffer.Reset() return nil } @@ -63,6 +65,16 @@ func (s *fileSink) newBuffers() severityWriters { return s.swap(severityWriters{new(flushBuffer), new(flushBuffer), new(flushBuffer), new(flushBuffer)}) } +func (s *fileSink) resetBuffers() { + s.mu.Lock() + defer s.mu.Unlock() + for _, buf := range s.file { + if buf != nil { + buf.Flush() + } + } +} + // contents returns the specified log value as a string. func contents(s logsink.Severity) string { return sinks.file.file[s].(*flushBuffer).String() @@ -82,12 +94,20 @@ func setFlags() { func TestInfo(t *testing.T) { setFlags() defer sinks.file.swap(sinks.file.newBuffers()) - Info("test") - if !contains(logsink.Info, "I", t) { - t.Errorf("Info has wrong character: %q", contents(logsink.Info)) + funcs := []func(args ...any){ + Info, + func(args ...any) { InfoContext(context.Background(), args) }, } - if !contains(logsink.Info, "test", t) { - t.Error("Info failed") + + for _, f := range funcs { + sinks.file.resetBuffers() + f("test") + if !contains(logsink.Info, "I", t) { + t.Errorf("Info has wrong character: %q", contents(logsink.Info)) + } + if !contains(logsink.Info, "test", t) { + t.Error("Info failed") + } } } @@ -95,42 +115,50 @@ func TestInfoDepth(t *testing.T) { setFlags() defer sinks.file.swap(sinks.file.newBuffers()) - f := func() { InfoDepth(1, "depth-test1") } + funcs := []func(d int, args ...any){ + InfoDepth, + func(d int, args ...any) { InfoContextDepth(context.Background(), d+1, args) }, + } - // The next three lines must stay together - _, _, wantLine, _ := runtime.Caller(0) - InfoDepth(0, "depth-test0") - f() + for _, infoDepth := range funcs { + sinks.file.resetBuffers() + f := func() { infoDepth(1, "depth-test1") } - msgs := strings.Split(strings.TrimSuffix(contents(logsink.Info), "\n"), "\n") - if len(msgs) != 2 { - t.Fatalf("Got %d lines, expected 2", len(msgs)) - } + // The next three lines must stay together + _, _, wantLine, _ := runtime.Caller(0) + infoDepth(0, "depth-test0") + f() - for i, m := range msgs { - if !strings.HasPrefix(m, "I") { - t.Errorf("InfoDepth[%d] has wrong character: %q", i, m) - } - w := fmt.Sprintf("depth-test%d", i) - if !strings.Contains(m, w) { - t.Errorf("InfoDepth[%d] missing %q: %q", i, w, m) + msgs := strings.Split(strings.TrimSuffix(contents(logsink.Info), "\n"), "\n") + if len(msgs) != 2 { + t.Fatalf("Got %d lines, expected 2", len(msgs)) } - // pull out the line number (between : and ]) - msg := m[strings.LastIndex(m, ":")+1:] - x := strings.Index(msg, "]") - if x < 0 { - t.Errorf("InfoDepth[%d]: missing ']': %q", i, m) - continue - } - line, err := strconv.Atoi(msg[:x]) - if err != nil { - t.Errorf("InfoDepth[%d]: bad line number: %q", i, m) - continue - } - wantLine++ - if wantLine != line { - t.Errorf("InfoDepth[%d]: got line %d, want %d", i, line, wantLine) + for i, m := range msgs { + if !strings.HasPrefix(m, "I") { + t.Errorf("InfoDepth[%d] has wrong character: %q", i, m) + } + w := fmt.Sprintf("depth-test%d", i) + if !strings.Contains(m, w) { + t.Errorf("InfoDepth[%d] missing %q: %q", i, w, m) + } + + // pull out the line number (between : and ]) + msg := m[strings.LastIndex(m, ":")+1:] + x := strings.Index(msg, "]") + if x < 0 { + t.Errorf("InfoDepth[%d]: missing ']': %q", i, m) + continue + } + line, err := strconv.Atoi(msg[:x]) + if err != nil { + t.Errorf("InfoDepth[%d]: bad line number: %q", i, m) + continue + } + wantLine++ + if wantLine != line { + t.Errorf("InfoDepth[%d]: got line %d, want %d", i, line, wantLine) + } } } } @@ -204,19 +232,28 @@ func TestHeader(t *testing.T) { func TestError(t *testing.T) { setFlags() defer sinks.file.swap(sinks.file.newBuffers()) - Error("test") - if !contains(logsink.Error, "E", t) { - t.Errorf("Error has wrong character: %q", contents(logsink.Error)) - } - if !contains(logsink.Error, "test", t) { - t.Error("Error failed") - } - str := contents(logsink.Error) - if !contains(logsink.Warning, str, t) { - t.Error("Warning failed") + + funcs := []func(args ...any){ + Error, + func(args ...any) { ErrorContext(context.Background(), args) }, } - if !contains(logsink.Info, str, t) { - t.Error("Info failed") + + for _, error := range funcs { + sinks.file.resetBuffers() + error("test") + if !contains(logsink.Error, "E", t) { + t.Errorf("Error has wrong character: %q", contents(logsink.Error)) + } + if !contains(logsink.Error, "test", t) { + t.Error("Error failed") + } + str := contents(logsink.Error) + if !contains(logsink.Warning, str, t) { + t.Error("Warning failed") + } + if !contains(logsink.Info, str, t) { + t.Error("Info failed") + } } } @@ -226,16 +263,25 @@ func TestError(t *testing.T) { func TestWarning(t *testing.T) { setFlags() defer sinks.file.swap(sinks.file.newBuffers()) - Warning("test") - if !contains(logsink.Warning, "W", t) { - t.Errorf("Warning has wrong character: %q", contents(logsink.Warning)) - } - if !contains(logsink.Warning, "test", t) { - t.Error("Warning failed") + + funcs := []func(args ...any){ + Warning, + func(args ...any) { WarningContext(context.Background(), args) }, } - str := contents(logsink.Warning) - if !contains(logsink.Info, str, t) { - t.Error("Info failed") + + for _, warning := range funcs { + sinks.file.resetBuffers() + warning("test") + if !contains(logsink.Warning, "W", t) { + t.Errorf("Warning has wrong character: %q", contents(logsink.Warning)) + } + if !contains(logsink.Warning, "test", t) { + t.Error("Warning failed") + } + str := contents(logsink.Warning) + if !contains(logsink.Info, str, t) { + t.Error("Info failed") + } } } @@ -248,12 +294,19 @@ func TestV(t *testing.T) { } defer flag.Lookup("v").Value.Set("0") - V(2).Info("test") - if !contains(logsink.Info, "I", t) { - t.Errorf("Info has wrong character: %q", contents(logsink.Info)) + funcs := []func(args ...any){ + V(2).Info, + func(args ...any) { V(2).InfoContext(context.Background(), args) }, } - if !contains(logsink.Info, "test", t) { - t.Error("Info failed") + for _, info := range funcs { + sinks.file.resetBuffers() + info("test") + if !contains(logsink.Info, "I", t) { + t.Errorf("Info has wrong character: %q", contents(logsink.Info)) + } + if !contains(logsink.Info, "test", t) { + t.Error("Info failed") + } } } diff --git a/go.mod b/go.mod index 2494cb8d..28e5678b 100644 --- a/go.mod +++ b/go.mod @@ -1,3 +1,5 @@ module github.com/golang/glog go 1.19 + +require github.com/google/go-cmp v0.6.0 // indirect diff --git a/go.sum b/go.sum new file mode 100644 index 00000000..5a8d551d --- /dev/null +++ b/go.sum @@ -0,0 +1,2 @@ +github.com/google/go-cmp v0.6.0 h1:ofyhxvXcZhMsU5ulbFiLKl/XBFqE1GSq7atu8tAmTRI= +github.com/google/go-cmp v0.6.0/go.mod h1:17dUlkBOakJ0+DkrSSNjCkIjxS6bF9zb3elmeNGIjoY= diff --git a/internal/logsink/logsink.go b/internal/logsink/logsink.go index 53758e1c..28c38a6a 100644 --- a/internal/logsink/logsink.go +++ b/internal/logsink/logsink.go @@ -16,6 +16,7 @@ package logsink import ( "bytes" + "context" "fmt" "strconv" "strings" @@ -77,6 +78,11 @@ func ParseSeverity(name string) (Severity, error) { // Meta is metadata about a logging call. type Meta struct { + // The context with which the log call was made (or nil). If set, the context + // is only valid during the logsink.Structured.Printf call, it should not be + // retained. + Context context.Context + // Time is the time at which the log call was made. Time time.Time diff --git a/internal/logsink/logsink_test.go b/internal/logsink/logsink_test.go new file mode 100644 index 00000000..34c06566 --- /dev/null +++ b/internal/logsink/logsink_test.go @@ -0,0 +1,629 @@ +package logsink_test + +import ( + "bytes" + "errors" + "math" + "reflect" + "runtime" + "slices" + "testing" + "time" + + "github.com/golang/glog/internal/logsink" + "github.com/golang/glog/internal/stackdump" + "github.com/google/go-cmp/cmp" +) + +// A savingTextSink saves the data argument of the last Emit call made to it. +type savingTextSink struct{ data []byte } + +func (savingTextSink) Enabled(*logsink.Meta) bool { return true } +func (s *savingTextSink) Emit(meta *logsink.Meta, data []byte) (n int, err error) { + s.data = slices.Clone(data) + return len(data), nil +} + +func TestThreadPadding(t *testing.T) { + originalSinks := logsink.StructuredSinks + defer func() { logsink.StructuredSinks = originalSinks }() + var sink savingTextSink + logsink.TextSinks = []logsink.Text{&sink} + + _, file, line, _ := runtime.Caller(0) + meta := &logsink.Meta{ + Time: time.Now(), + File: file, + Line: line, + Severity: logsink.Info, + } + + const msg = "DOOMBAH!" + + for _, tc := range [...]struct { + n uint64 + want []byte + }{ + // Integers that encode as fewer than 7 ASCII characters are padded, the + // rest is not; see nDigits(). + {want: []byte(" "), n: 0}, // nDigits does not support 0 (I presume for speed reasons). + {want: []byte(" 1 "), n: 1}, + {want: []byte(" 912389 "), n: 912389}, + {want: []byte(" 2147483648 "), n: math.MaxInt32 + 1}, + {want: []byte(" 9223372036854775806 "), n: math.MaxInt64 - 1}, + {want: []byte(" 9223372036854775808 "), n: math.MaxInt64 + 1}, // Test int64 overflow. + {want: []byte(" 9223372036854775817 "), n: math.MaxInt64 + 10}, // Test int64 overflow. + {want: []byte(" 18446744073709551614 "), n: math.MaxUint64 - 1}, // Test int64 overflow. + } { + meta.Thread = int64(tc.n) + logsink.Printf(meta, "%v", msg) + t.Logf(`logsink.Printf(%+v, "%%v", %q)`, meta, msg) + + // Check if the needle is present exactly. + if !bytes.Contains(sink.data, tc.want) { + t.Errorf("needle = '%s' not found in %s", tc.want, sink.data) + } + } +} + +func TestFatalMessage(t *testing.T) { + const msg = "DOOOOOOM!" + + _, file, line, _ := runtime.Caller(0) + meta := &logsink.Meta{ + Time: time.Now(), + File: file, + Line: line, + Severity: logsink.Fatal, + } + + logsink.Printf(meta, "%v", msg) + t.Logf(`logsink.Printf(%+v, "%%v", %q)`, meta, msg) + + gotMeta, gotMsg, ok := logsink.FatalMessage() + if !ok || !reflect.DeepEqual(gotMeta, meta) || !bytes.Contains(gotMsg, []byte(msg)) { + t.Errorf("logsink.FatalMessage() = %+v, %q, %v", gotMeta, gotMsg, ok) + } +} + +func TestStructuredSink(t *testing.T) { + // Reset logsink.StructuredSinks at the end of the test. + // Each test case will clear it and insert its own test sink. + originalSinks := logsink.StructuredSinks + defer func() { + logsink.StructuredSinks = originalSinks + }() + + testStacktrace := stackdump.Caller(0) + + for _, test := range []struct { + name string + format string + args []any + meta logsink.Meta + wantErr bool + sinks []testStructuredSinkAndWants + }{ + { + name: "sink is called with expected format and args", + format: "test %d", + args: []any{1}, + sinks: []testStructuredSinkAndWants{ + { + sink: &fakeStructuredSink{}, + }, + }, + }, + { + name: "sink is called with expected meta", + meta: logsink.Meta{ + Severity: logsink.Info, + File: "base/go/logsink_test.go", + Line: 1, + Time: time.Unix(1545321163, 0), + Thread: 1, + }, + sinks: []testStructuredSinkAndWants{ + { + sink: &fakeStructuredSink{}, + }, + }, + }, + { + name: "sink is called with expected meta (2)", + meta: logsink.Meta{ + Severity: logsink.Error, + File: "foo.go", + Line: 1337, + Time: time.Unix(0, 0), + Thread: 123, + }, + sinks: []testStructuredSinkAndWants{ + { + sink: &fakeStructuredSink{}, + }, + }, + }, + { + name: "sink returns error", + format: "test", + meta: logsink.Meta{ + Severity: logsink.Info, + File: "base/go/logsink_test.go", + Line: 1, + Time: time.Unix(1545321163, 0), + Thread: 1, + }, + wantErr: true, + sinks: []testStructuredSinkAndWants{ + { + sink: &fakeStructuredSink{ + err: errors.New("err"), + }, + }, + }, + }, + { + name: "sink is StackWanter and WantStack() returns true", + sinks: []testStructuredSinkAndWants{ + { + sink: &fakeStructuredSinkThatWantsStack{ + wantStack: true, + }, + wantStack: true, + }, + }, + }, + { + name: "sink is StackWanter and WantStack() returns false", + sinks: []testStructuredSinkAndWants{ + { + sink: &fakeStructuredSinkThatWantsStack{ + wantStack: false, + }, + wantStack: false, + }, + }, + }, + { + name: "use stacktrace from args if available", + format: "test\n%s", + args: []any{testStacktrace}, + sinks: []testStructuredSinkAndWants{ + { + sink: &fakeStructuredSinkThatWantsStack{ + wantStack: true, + }, + wantStack: true, + wantStackEqual: &testStacktrace, + }, + }, + }, + { + name: "respect StackWanter contract", + format: "test\n%s", + args: []any{testStacktrace}, + sinks: []testStructuredSinkAndWants{ + { + sink: &fakeStructuredSinkThatWantsStack{ + wantStack: true, + }, + wantStack: true, + wantStackEqual: &testStacktrace, + }, + { + sink: &fakeStructuredSink{}, + }, + }, + }, + { + name: "respect StackWanter contract for multiple sinks", + format: "test\n%s", + args: []any{testStacktrace}, + sinks: []testStructuredSinkAndWants{ + { + sink: &fakeStructuredSinkThatWantsStack{wantStack: true}, + wantStack: true, + wantStackEqual: &testStacktrace, + }, + { + sink: &fakeStructuredSinkThatWantsStack{wantStack: false}, + wantStack: false, + }, + { + sink: &fakeStructuredSinkThatWantsStack{wantStack: true}, + wantStack: true, + wantStackEqual: &testStacktrace, + }, + { + sink: &fakeStructuredSink{}, + wantStack: false, + }, + { + sink: &fakeStructuredSinkThatWantsStack{wantStack: true}, + wantStack: true, + wantStackEqual: &testStacktrace, + }, + }, + }, + } { + t.Run(test.name, func(t *testing.T) { + testStructuredSinks := make([]logsink.Structured, len(test.sinks)) + for i, sink := range test.sinks { + testStructuredSinks[i] = sink.sink + } + // Register test logsinks + logsink.StructuredSinks = testStructuredSinks + + // logsink.Printf() should call Printf() on all registered logsinks. + // Copy test.meta to prevent changes by the code under test. + meta := test.meta + _, err := logsink.Printf(&meta, test.format, test.args...) + if gotErr := err != nil; gotErr != test.wantErr { + t.Fatalf("logsink.Printf() = (_, %v), want err? %t", err, test.wantErr) + } + + // Test the behavior for each registered StructuredSink. + for _, testStructuredSinkAndWants := range test.sinks { + // Check that the test logsink was called with expected arguments. + if got, want := testStructuredSinkAndWants.sink.Calls(), 1; got != want { + t.Fatalf("sink.calls = %d, want %d", got, want) + } + + // Check that Meta was passed through to the logsink. + gotMeta := testStructuredSinkAndWants.sink.GotMeta() + // Ignore the Stack and Depth fields; these will be checked further down. + cmpIgnoreSomeFields := cmp.FilterPath(func(p cmp.Path) bool { return p.String() == "Stack" || p.String() == "Depth" }, cmp.Ignore()) + if diff := cmp.Diff(&test.meta, gotMeta, cmpIgnoreSomeFields); diff != "" { + t.Errorf("sink.meta diff -want +got:\n%s", diff) + } + + // The contract is: + // - If WantStack is true, a Stack is present. + // - If WantStack is false, a Stack may be present. + if testStructuredSinkAndWants.wantStack && gotMeta.Stack == nil { + t.Errorf("sink.meta.Stack = %v, but WantStack = %t", gotMeta.Stack, testStructuredSinkAndWants.wantStack) + } else if testStructuredSinkAndWants.wantStackEqual != nil { + // We have a stack, but is it the right one? + if diff := cmp.Diff(testStructuredSinkAndWants.wantStackEqual, gotMeta.Stack); diff != "" { + t.Errorf("sink.meta.Stack diff -want +got:\n%s", diff) + } + } + + // Depth should be 1, since test.meta.Depth is always 0 and there's a single + // function call, logsink.Printf(), between here and the logsink. + if got, want := gotMeta.Depth, 1; got != want { + t.Errorf("sink.meta.Depth = %d, want %d", got, want) + } + + if got, want := testStructuredSinkAndWants.sink.GotFormat(), test.format; got != want { + t.Errorf("sink.format = %q, want %q", got, want) + } + + if diff := cmp.Diff(test.args, testStructuredSinkAndWants.sink.GotArgs()); diff != "" { + t.Errorf("sink.args diff -want +got:\n%s", diff) + } + } + }) + } +} + +func BenchmarkStructuredSink(b *testing.B) { + // Reset logsink.StructuredSinks at the end of the benchmark. + // Each benchmark case will clear it and insert its own test sink. + originalSinks := logsink.StructuredSinks + defer func() { + logsink.StructuredSinks = originalSinks + }() + + noop := noopStructuredSink{} + noopWS := noopStructuredSinkWantStack{} + stringWS := stringStructuredSinkWantStack{} + + _, file, line, _ := runtime.Caller(0) + stack := stackdump.Caller(0) + genMeta := func(dump *stackdump.Stack) *logsink.Meta { + return &logsink.Meta{ + Time: time.Now(), + File: file, + Line: line, + Severity: logsink.Warning, + Thread: 1240, + Stack: dump, + } + } + + for _, test := range []struct { + name string + sinks []logsink.Structured + meta *logsink.Meta + }{ + {name: "meta_nostack_01_sinks_00_want_stack_pconly", meta: genMeta(nil), sinks: []logsink.Structured{noop}}, + {name: "meta___stack_01_sinks_01_want_stack_pconly", meta: genMeta(&stack), sinks: []logsink.Structured{noopWS}}, + {name: "meta_nostack_01_sinks_01_want_stack_pconly", meta: genMeta(nil), sinks: []logsink.Structured{noopWS}}, + {name: "meta_nostack_01_sinks_01_want_stack_string", meta: genMeta(nil), sinks: []logsink.Structured{stringWS}}, + {name: "meta_nostack_02_sinks_01_want_stack_pconly", meta: genMeta(nil), sinks: []logsink.Structured{noopWS, noop}}, + {name: "meta_nostack_02_sinks_02_want_stack_string", meta: genMeta(nil), sinks: []logsink.Structured{stringWS, stringWS}}, + {name: "meta_nostack_10_sinks_00_want_stack_pconly", meta: genMeta(nil), sinks: []logsink.Structured{noop, noop, noop, noop, noop, noop, noop, noop, noop, noop}}, + {name: "meta_nostack_10_sinks_05_want_stack_pconly", meta: genMeta(nil), sinks: []logsink.Structured{noop, noopWS, noop, noop, noopWS, noop, noopWS, noopWS, noopWS, noop}}, + {name: "meta_nostack_10_sinks_05_want_stack_string", meta: genMeta(nil), sinks: []logsink.Structured{noop, stringWS, noop, noop, stringWS, noop, stringWS, stringWS, stringWS, noop}}, + {name: "meta___stack_10_sinks_05_want_stack_pconly", meta: genMeta(&stack), sinks: []logsink.Structured{noop, noopWS, noop, noop, noopWS, noop, noopWS, noopWS, noopWS, noop}}, + {name: "meta___stack_10_sinks_05_want_stack_string", meta: genMeta(&stack), sinks: []logsink.Structured{noop, stringWS, noop, noop, stringWS, noop, stringWS, stringWS, stringWS, noop}}, + } { + b.Run(test.name, func(b *testing.B) { + logsink.StructuredSinks = test.sinks + savedStack := test.meta.Stack + + args := []any{1} // Pre-allocate args slice to avoid allocation in benchmark loop. + + b.ResetTimer() + for i := 0; i < b.N; i++ { + _, err := logsink.Printf(test.meta, "test %d", args...) + if err != nil { + b.Fatalf("logsink.Printf(): didn't expect any error while benchmarking, got %v", err) + } + // logsink.Printf modifies Meta.Depth, which is used during stack + // collection. If we don't reset it, stacks quickly become empty, making + // the benchmark useless. + test.meta.Depth = 0 + // There is a possible optimization where logsink.Printf will avoid + // allocating a new meta and modify it in-place if it needs a stack. + // This would throw off benchmarks as subsequent invocations would + // re-use this stack. Since we know this memoization/modification only + // happens with stacks, reset it manually to avoid skewing allocation + // numbers. + test.meta.Stack = savedStack + } + }) + } +} + +// testStructuredSinkAndWants contains a StructuredSink under test +// and its wanted values. The struct is created to help with testing +// multiple StructuredSinks for Printf(). +type testStructuredSinkAndWants struct { + // The sink under test. + sink testStructuredSink + // Whether this sink should want stack in its meta. + // Only set when the sink is fakeStructuredSinkThatWantsStack. + wantStack bool + // If this sink wants stack, the expected stack. + // Only set when the sink is fakeStructuredSinkThatWantsStack and returns true for WantStack(). + wantStackEqual *stackdump.Stack +} + +type testStructuredSink interface { + logsink.Structured + + GotMeta() *logsink.Meta + GotFormat() string + GotArgs() []any + Calls() int +} + +type fakeStructuredSink struct { + // err is returned by Printf(). + err error + // gotMeta is the Meta passed to the last Printf() call. + gotMeta *logsink.Meta + // gotFormat is the format string passed to the last Printf() call. + gotFormat string + // gotArgs are the arguments passed to the last Printf() call. + gotArgs []any + // calls is a counter of the number of times Printf() has been called. + calls int +} + +func (s *fakeStructuredSink) GotMeta() *logsink.Meta { + return s.gotMeta +} + +func (s *fakeStructuredSink) GotFormat() string { + return s.gotFormat +} + +func (s *fakeStructuredSink) GotArgs() []any { + return s.gotArgs +} + +func (s *fakeStructuredSink) Calls() int { + return s.calls +} + +func (s *fakeStructuredSink) Printf(meta *logsink.Meta, format string, a ...any) (n int, err error) { + s.gotMeta = meta + s.gotFormat = format + s.gotArgs = a + s.calls++ + return 0, s.err +} + +type fakeStructuredSinkThatWantsStack struct { + fakeStructuredSink + // wantStack controls what the WantStack() method returns. + wantStack bool +} + +func (s *fakeStructuredSinkThatWantsStack) WantStack(meta *logsink.Meta) bool { + return s.wantStack +} + +type noopStructuredSink struct{} + +func (s noopStructuredSink) Printf(meta *logsink.Meta, format string, a ...any) (n int, err error) { + return 0, nil +} + +type noopStructuredSinkWantStack struct{} + +func (s noopStructuredSinkWantStack) WantStack(_ *logsink.Meta) bool { return true } +func (s noopStructuredSinkWantStack) Printf(meta *logsink.Meta, format string, a ...any) (n int, err error) { + return 0, nil +} + +type stringStructuredSinkWantStack struct{} + +func (s stringStructuredSinkWantStack) WantStack(_ *logsink.Meta) bool { return true } +func (s stringStructuredSinkWantStack) Printf(meta *logsink.Meta, format string, a ...any) (n int, err error) { + return len(meta.Stack.String()), nil +} + +// TestStructuredTextWrapper tests StructuredTextWrapper.Printf(). +// It validates the input received by each Text sink in StructuredTextWrapper.TextSinks +// by comparing it to the input received by a Text sink in logsink.TextSinks. We assume +// that logsink.TextSinks receives a correct input (that fact is already tested in log.test.go) +func TestStructuredTextWrapper(t *testing.T) { + // Reset logsink.TextSinks at the end of the test. + originalTextSinks := logsink.TextSinks + defer func() { + logsink.TextSinks = originalTextSinks + }() + + // The input received by the `reference` sink will be used to validate the input received by + // each sink in StructuredTextWrapper.TextSinks. + reference := fakeTextSink{enabled: true} + logsink.TextSinks = []logsink.Text{&reference} + + meta := logsink.Meta{ + Severity: logsink.Info, + File: "base/go/logsink_test.go", + Line: 1, + Time: time.Unix(1545321163, 0), + Thread: 1, + } + format := "test %d" + args := []any{1} + + for _, test := range []struct { + name string + sinks []fakeTextSink + wantByteCount int + wantErr bool + }{ + { + name: "no sinks", + sinks: []fakeTextSink{}, + }, + { + name: "single sink", + sinks: []fakeTextSink{ + fakeTextSink{enabled: true, byteCount: 300}, + }, + wantByteCount: 300, + }, + { + name: "multiple sinks", + sinks: []fakeTextSink{ + fakeTextSink{enabled: true, byteCount: 100}, + fakeTextSink{enabled: true, byteCount: 300}, + fakeTextSink{enabled: true, byteCount: 200}, + }, + wantByteCount: 300, + }, + { + name: "some sinks disabled", + sinks: []fakeTextSink{ + fakeTextSink{enabled: true, byteCount: 100}, + fakeTextSink{enabled: true, byteCount: 200}, + fakeTextSink{}, + fakeTextSink{}, + }, + wantByteCount: 200, + }, + { + name: "all sinks disabled", + sinks: []fakeTextSink{ + fakeTextSink{}, + fakeTextSink{}, + fakeTextSink{}, + }, + }, + { + name: "error", + sinks: []fakeTextSink{ + fakeTextSink{enabled: true, byteCount: 100}, + fakeTextSink{enabled: true, err: errors.New("err")}, + fakeTextSink{enabled: true, byteCount: 200}, + }, + wantErr: true, + }, + } { + t.Run(test.name, func(t *testing.T) { + wrapper := logsink.StructuredTextWrapper{} + for i := range test.sinks { + wrapper.TextSinks = append(wrapper.TextSinks, &test.sinks[i]) + } + + // Writing to reference sink. + // Copy meta to prevent changes by the code under test. + m := meta + if _, err := logsink.Printf(&m, format, args); err != nil { + t.Fatalf("failed to write to reference sink: %v", err) + } + + // Writing to StructuredTextWrapper. + // Copy meta to prevent changes by the code under test. + m = meta + n, err := wrapper.Printf(&m, format, args) + + if gotErr := err != nil; gotErr != test.wantErr { + t.Fatalf("StructuredTextWrapper.Printf() returned err=%v, want err? %t", err, test.wantErr) + } + + // If an error is expected, we are done. + if err != nil { + return + } + + if n != test.wantByteCount { + t.Fatalf("StructuredTextWrapper.Printf() returned n=%v, want %v", n, test.wantByteCount) + } + + for i, sink := range test.sinks { + if sink.enabled { + if got, want := sink.calls, 1; got != want { + t.Fatalf("sinks[%v].calls = %d, want %d", i, got, want) + } + + if diff := cmp.Diff(&meta, sink.gotMeta); diff != "" { + t.Errorf("sinks[%v].meta diff -want +got:\n%s", i, diff) + } + + if got, want := sink.gotBytes, reference.gotBytes; bytes.Compare(got, want) != 0 { + t.Errorf("sinks[%v].bytes = %s, want %s", i, got, want) + } + } else { + if got, want := sink.calls, 0; got != want { + t.Fatalf("sinks[%v].calls = %d, want %d", i, got, want) + } + } + } + }) + } +} + +type fakeTextSink struct { + // enabled is returned by Enabled(). + enabled bool + // byteCount is returned by Emit(). + byteCount int + // err is returned by Emit(). + err error + // gotMeta is the Meta passed to the last Emit() call. + gotMeta *logsink.Meta + // gotBytes is the byte slice passed to the last Emit() call. + gotBytes []byte + // calls is a counter of the number of times Emit() has been called. + calls int +} + +func (s *fakeTextSink) Enabled(meta *logsink.Meta) bool { + return s.enabled +} + +func (s *fakeTextSink) Emit(meta *logsink.Meta, bytes []byte) (n int, err error) { + s.gotMeta = meta + s.gotBytes = bytes + s.calls++ + return s.byteCount, s.err +}