From b256bbe5d3f846c1d1ce73030c10973378e04cf0 Mon Sep 17 00:00:00 2001 From: Chressie Himpel Date: Wed, 22 Nov 2023 07:00:33 +0100 Subject: [PATCH] glog: add context variants to most log functions We export this new API to make the internal and external versions identical. The context is currently plumbed through to the internal/logsink package, but effectively discarded there. cl/560684897 (google-internal) cl/579771826 (google-internal) --- glog.go | 201 ++++++++++++++++++++++++++++++++++-- glog_context_test.go | 62 +++++++++++ glog_test.go | 177 ++++++++++++++++++++----------- internal/logsink/logsink.go | 6 ++ 4 files changed, 376 insertions(+), 70 deletions(-) create mode 100644 glog_context_test.go 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/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