cmd/log: move stackdriver logging to its own package

This change breaks out the stackdriver logging to its own package. It
also only does logging of trace ids and labels to the stackdriver
logger, to keep the logging interface simple.

For golang/go#61399

Change-Id: I9a25d0c6391d1667fe476e5fdc30fc057f07c40f
Reviewed-on: https://go-review.googlesource.com/c/pkgsite/+/515375
TryBot-Result: Gopher Robot <[email protected]>
kokoro-CI: kokoro <[email protected]>
Run-TryBot: Michael Matloob <[email protected]>
Reviewed-by: Jamal Carvalho <[email protected]>

Author: matloob

cmd/internal/cmdconfig/cmdconfig.go

@@ -22,6 +22,7 @@ import (
 	"golang.org/x/pkgsite/internal/database"
 	"golang.org/x/pkgsite/internal/derrors"
 	"golang.org/x/pkgsite/internal/log"
+	"golang.org/x/pkgsite/internal/log/stackdriverlogger"
 	"golang.org/x/pkgsite/internal/middleware"
 	"golang.org/x/pkgsite/internal/postgres"
 )
@@ -36,11 +37,12 @@ func Logger(ctx context.Context, cfg *config.Config, logName string) middleware.
 				"k8s-pod/app": cfg.Application(),
 			}))
 		}
-		logger, err := log.UseStackdriver(ctx, logName, cfg.ProjectID, opts)
+		logger, parent, err := stackdriverlogger.New(ctx, logName, cfg.ProjectID, opts)
+		log.Use(logger)
 		if err != nil {
 			log.Fatal(ctx, err)
 		}
-		return logger
+		return parent
 	}
 	return middleware.LocalLogger{}
 }

internal/log/log.go

@@ -7,35 +7,57 @@ package log
 
 import (
 	"context"
-	"errors"
 	"fmt"
 	"log"
 	"os"
 	"strings"
 	"sync"
 
-	"cloud.google.com/go/logging"
-	"golang.org/x/pkgsite/internal/derrors"
 	"golang.org/x/pkgsite/internal/experiment"
 )
 
+type Severity int
+
+const (
+	SeverityDefault = Severity(iota)
+	SeverityDebug
+	SeverityInfo
+	SeverityWarning
+	SeverityError
+	SeverityCritical
+)
+
+func (s Severity) String() string {
+	switch s {
+	case SeverityDefault:
+		return "Default"
+	case SeverityDebug:
+		return "Debug"
+	case SeverityInfo:
+		return "Info"
+	case SeverityWarning:
+		return "Warning"
+	case SeverityError:
+		return "Error"
+	case SeverityCritical:
+		return "Critical"
+	default:
+		return fmt.Sprint(int(s))
+	}
+}
+
+type Logger interface {
+	Log(ctx context.Context, s Severity, payload any)
+	Flush()
+}
+
 var (
 	mu     sync.Mutex
-	logger interface {
-		log(context.Context, logging.Severity, any)
-	} = stdlibLogger{}
+	logger Logger = stdlibLogger{}
 
 	// currentLevel holds current log level.
 	// No logs will be printed below currentLevel.
-	currentLevel = logging.Default
-)
-
-type (
-	// traceIDKey is the type of the context key for trace IDs.
-	traceIDKey struct{}
-
-	// labelsKey is the type of the context key for labels.
-	labelsKey struct{}
+	currentLevel = SeverityDefault
 )
 
 // Set the log level
@@ -45,79 +67,17 @@ func SetLevel(v string) {
 	currentLevel = toLevel(v)
 }
 
-func getLevel() logging.Severity {
+func getLevel() Severity {
 	mu.Lock()
 	defer mu.Unlock()
 	return currentLevel
 }
 
-// NewContextWithTraceID creates a new context from ctx that adds the trace ID.
-func NewContextWithTraceID(ctx context.Context, traceID string) context.Context {
-	return context.WithValue(ctx, traceIDKey{}, traceID)
-}
-
-// NewContextWithLabel creates anew context from ctx that adds a label that will
-// appear in the log entry.
-func NewContextWithLabel(ctx context.Context, key, value string) context.Context {
-	oldLabels, _ := ctx.Value(labelsKey{}).(map[string]string)
-	// Copy the labels, to preserve immutability of contexts.
-	newLabels := map[string]string{}
-	for k, v := range oldLabels {
-		newLabels[k] = v
-	}
-	newLabels[key] = value
-	return context.WithValue(ctx, labelsKey{}, newLabels)
-}
-
-// stackdriverLogger logs to GCP Stackdriver.
-type stackdriverLogger struct {
-	sdlogger *logging.Logger
-}
-
-func (l *stackdriverLogger) log(ctx context.Context, s logging.Severity, payload any) {
-	// Convert errors to strings, or they may serialize as the empty JSON object.
-	if err, ok := payload.(error); ok {
-		payload = err.Error()
-	}
-	traceID, _ := ctx.Value(traceIDKey{}).(string) // if not present, traceID is "", which is fine
-	labels, _ := ctx.Value(labelsKey{}).(map[string]string)
-	es := experimentString(ctx)
-	if len(es) > 0 {
-		nl := map[string]string{}
-		for k, v := range labels {
-			nl[k] = v
-		}
-		nl["experiments"] = es
-		labels = nl
-	}
-	l.sdlogger.Log(logging.Entry{
-		Severity: s,
-		Labels:   labels,
-		Payload:  payload,
-		Trace:    traceID,
-	})
-}
-
 // stdlibLogger uses the Go standard library logger.
 type stdlibLogger struct{}
 
-func init() {
-	// Log to stdout on GKE so the log messages are severity Info, rather than Error.
-	if os.Getenv("GO_DISCOVERY_ON_GKE") != "" {
-		log.SetOutput(os.Stdout)
-
-	}
-}
-
-func (stdlibLogger) log(ctx context.Context, s logging.Severity, payload any) {
+func (stdlibLogger) Log(ctx context.Context, s Severity, payload any) {
 	var extras []string
-	traceID, _ := ctx.Value(traceIDKey{}).(string) // if not present, traceID is ""
-	if traceID != "" {
-		extras = append(extras, fmt.Sprintf("traceID %s", traceID))
-	}
-	if labels, ok := ctx.Value(labelsKey{}).(map[string]string); ok {
-		extras = append(extras, fmt.Sprint(labels))
-	}
 	es := experimentString(ctx)
 	if len(es) > 0 {
 		extras = append(extras, fmt.Sprintf("experiments %s", es))
@@ -130,126 +90,106 @@ func (stdlibLogger) log(ctx context.Context, s logging.Severity, payload any) {
 
 }
 
+func (stdlibLogger) Flush() {}
+
 func experimentString(ctx context.Context) string {
 	return strings.Join(experiment.FromContext(ctx).Active(), ", ")
 }
 
-// UseStackdriver switches from the default stdlib logger to a Stackdriver
-// logger. It assumes config.Init has been called. UseStackdriver returns a
-// "parent" *logging.Logger that should be used to log the start and end of a
-// request. It also creates and remembers internally a "child" logger that will
-// be used to log within a request. The two loggers are necessary to get request-scoped
-// logs in Stackdriver.
-// See https://cloud.google.com/appengine/docs/standard/go/writing-application-logs.
-//
-// UseStackdriver can only be called once. If it is called a second time, it returns an error.
-func UseStackdriver(ctx context.Context, logName, projectID string, opts []logging.LoggerOption) (_ *logging.Logger, err error) {
-	defer derrors.Wrap(&err, "UseStackdriver(ctx, %q)", logName)
-	client, err := logging.NewClient(ctx, projectID)
-	if err != nil {
-		return nil, err
-	}
-	parent := client.Logger(logName, opts...)
-	child := client.Logger(logName+"-child", opts...)
+func Use(l Logger) {
 	mu.Lock()
 	defer mu.Unlock()
-	if _, ok := logger.(*stackdriverLogger); ok {
-		return nil, errors.New("already called once")
-	}
-	logger = &stackdriverLogger{child}
-	return parent, nil
+	logger = l
 }
 
 // Infof logs a formatted string at the Info level.
 func Infof(ctx context.Context, format string, args ...any) {
-	logf(ctx, logging.Info, format, args)
+	logf(ctx, SeverityInfo, format, args)
 }
 
 // Warningf logs a formatted string at the Warning level.
 func Warningf(ctx context.Context, format string, args ...any) {
-	logf(ctx, logging.Warning, format, args)
+	logf(ctx, SeverityWarning, format, args)
 }
 
 // Errorf logs a formatted string at the Error level.
 func Errorf(ctx context.Context, format string, args ...any) {
-	logf(ctx, logging.Error, format, args)
+	logf(ctx, SeverityError, format, args)
 }
 
 // Debugf logs a formatted string at the Debug level.
 func Debugf(ctx context.Context, format string, args ...any) {
-	logf(ctx, logging.Debug, format, args)
+	logf(ctx, SeverityDebug, format, args)
 }
 
 // Fatalf logs formatted string at the Critical level followed by exiting the program.
 func Fatalf(ctx context.Context, format string, args ...any) {
-	logf(ctx, logging.Critical, format, args)
+	logf(ctx, SeverityCritical, format, args)
 	die()
 }
 
-func logf(ctx context.Context, s logging.Severity, format string, args []any) {
+func logf(ctx context.Context, s Severity, format string, args []any) {
 	doLog(ctx, s, fmt.Sprintf(format, args...))
 }
 
 // Info logs arg, which can be a string or a struct, at the Info level.
-func Info(ctx context.Context, arg any) { doLog(ctx, logging.Info, arg) }
+func Info(ctx context.Context, arg any) { doLog(ctx, SeverityInfo, arg) }
 
 // Warning logs arg, which can be a string or a struct, at the Warning level.
-func Warning(ctx context.Context, arg any) { doLog(ctx, logging.Warning, arg) }
+func Warning(ctx context.Context, arg any) { doLog(ctx, SeverityWarning, arg) }
 
 // Error logs arg, which can be a string or a struct, at the Error level.
-func Error(ctx context.Context, arg any) { doLog(ctx, logging.Error, arg) }
+func Error(ctx context.Context, arg any) { doLog(ctx, SeverityError, arg) }
 
 // Debug logs arg, which can be a string or a struct, at the Debug level.
-func Debug(ctx context.Context, arg any) { doLog(ctx, logging.Debug, arg) }
+func Debug(ctx context.Context, arg any) { doLog(ctx, SeverityDebug, arg) }
 
 // Fatal logs arg, which can be a string or a struct, at the Critical level followed by exiting the program.
 func Fatal(ctx context.Context, arg any) {
-	doLog(ctx, logging.Critical, arg)
+	doLog(ctx, SeverityCritical, arg)
 	die()
 }
 
-func doLog(ctx context.Context, s logging.Severity, payload any) {
+func doLog(ctx context.Context, s Severity, payload any) {
 	if getLevel() > s {
 		return
 	}
 	mu.Lock()
 	l := logger
 	mu.Unlock()
-	l.log(ctx, s, payload)
+	l.Log(ctx, s, payload)
 }
 
 func die() {
 	mu.Lock()
-	if sl, ok := logger.(*stackdriverLogger); ok {
-		sl.sdlogger.Flush()
-	}
+	logger.Flush()
 	mu.Unlock()
 	os.Exit(1)
 }
 
 // toLevel returns the logging.Severity for a given string.
 // Possible input values are "", "debug", "info", "warning", "error", "fatal".
 // In case of invalid string input, it maps to DefaultLevel.
-func toLevel(v string) logging.Severity {
+func toLevel(v string) Severity {
 	v = strings.ToLower(v)
 
 	switch v {
 	case "":
 		// default log level will print everything.
-		return logging.Default
+		return SeverityDefault
 	case "debug":
-		return logging.Debug
+		return SeverityDebug
 	case "info":
-		return logging.Info
+		return SeverityInfo
 	case "warning":
-		return logging.Warning
+		return SeverityWarning
 	case "error":
-		return logging.Error
+		return SeverityError
 	case "fatal":
-		return logging.Critical
+		return SeverityCritical
 	}
 
 	// Default log level in case of invalid input.
 	log.Printf("Error: %s is invalid LogLevel. Possible values are [debug, info, warning, error, fatal]", v)
-	return logging.Default
+	return SeverityDefault
 }

internal/log/log_test.go

@@ -9,8 +9,6 @@ import (
 	"fmt"
 	"strings"
 	"testing"
-
-	"cloud.google.com/go/logging"
 )
 
 const (
@@ -27,15 +25,15 @@ func TestSetLogLevel(t *testing.T) {
 	tests := []struct {
 		name      string
 		newLevel  string
-		wantLevel logging.Severity
+		wantLevel Severity
 	}{
-		{name: "default level", newLevel: "", wantLevel: logging.Default},
-		{name: "invalid level", newLevel: "xyz", wantLevel: logging.Default},
-		{name: "debug level", newLevel: "debug", wantLevel: logging.Debug},
-		{name: "info level", newLevel: "info", wantLevel: logging.Info},
-		{name: "warning level", newLevel: "warning", wantLevel: logging.Warning},
-		{name: "error level", newLevel: "error", wantLevel: logging.Error},
-		{name: "fatal level", newLevel: "fatal", wantLevel: logging.Critical},
+		{name: "default level", newLevel: "", wantLevel: SeverityDefault},
+		{name: "invalid level", newLevel: "xyz", wantLevel: SeverityDefault},
+		{name: "debug level", newLevel: "debug", wantLevel: SeverityDebug},
+		{name: "info level", newLevel: "info", wantLevel: SeverityInfo},
+		{name: "warning level", newLevel: "warning", wantLevel: SeverityWarning},
+		{name: "error level", newLevel: "error", wantLevel: SeverityError},
+		{name: "fatal level", newLevel: "fatal", wantLevel: SeverityCritical},
 	}
 	for _, test := range tests {
 		t.Run(test.name, func(t *testing.T) {
@@ -118,6 +116,8 @@ type mockLogger struct {
 	logs string
 }
 
-func (l *mockLogger) log(ctx context.Context, s logging.Severity, payload any) {
+func (l *mockLogger) Log(ctx context.Context, s Severity, payload any) {
 	l.logs += fmt.Sprintf("%s: %+v", s, payload)
 }
+
+func (l *mockLogger) Flush() {}