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)

Author: chressie

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...)
+}

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)
+	}
+}

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,55 +94,71 @@ 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")
+		}
 	}
 }
 
 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")
+		}
 	}
 }
 

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