From 5237f1872710d7e174a34d654dc7835c73adf597 Mon Sep 17 00:00:00 2001 From: Michael Matloob Date: Tue, 1 Aug 2023 15:43:37 -0400 Subject: [PATCH] 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 kokoro-CI: kokoro Run-TryBot: Michael Matloob Reviewed-by: Jamal Carvalho --- cmd/internal/cmdconfig/cmdconfig.go | 6 +- internal/log/log.go | 190 +++++++++----------------- internal/log/log_test.go | 22 +-- internal/log/stackdriverlogger/log.go | 146 ++++++++++++++++++++ internal/middleware/requestlog.go | 3 +- internal/worker/fetch.go | 3 +- 6 files changed, 230 insertions(+), 140 deletions(-) create mode 100644 internal/log/stackdriverlogger/log.go diff --git a/cmd/internal/cmdconfig/cmdconfig.go b/cmd/internal/cmdconfig/cmdconfig.go index f26ceb7ef..e5a7ee286 100644 --- a/cmd/internal/cmdconfig/cmdconfig.go +++ b/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{} } diff --git a/internal/log/log.go b/internal/log/log.go index ea38b9bc6..60c9371a0 100644 --- a/internal/log/log.go +++ b/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,99 +90,79 @@ 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) } @@ -230,26 +170,26 @@ func die() { // 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 } diff --git a/internal/log/log_test.go b/internal/log/log_test.go index d65587531..791bd7752 100644 --- a/internal/log/log_test.go +++ b/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() {} diff --git a/internal/log/stackdriverlogger/log.go b/internal/log/stackdriverlogger/log.go new file mode 100644 index 000000000..184e858a6 --- /dev/null +++ b/internal/log/stackdriverlogger/log.go @@ -0,0 +1,146 @@ +// Copyright 2019 The Go Authors. All rights reserved. +// Use of this source code is governed by a BSD-style +// license that can be found in the LICENSE file. + +// Package log supports structured and unstructured logging with levels +// to GCP stackdriver. +package stackdriverlogger + +import ( + "context" + "errors" + "fmt" + stdlog "log" + "os" + "strings" + "sync" + + "cloud.google.com/go/logging" + "golang.org/x/pkgsite/internal/derrors" + "golang.org/x/pkgsite/internal/experiment" + "golang.org/x/pkgsite/internal/log" +) + +func init() { + // Log to stdout on GKE so the log messages are severity Info, rather than Error. + if os.Getenv("GO_DISCOVERY_ON_GKE") != "" { + // Question for the reviewer. Was this meant to be done for cmd/pkgsite? This + // package won't be depended on by cmd/pkgsite, so that behavior will change, but + // we don't want the core to have knowledge of the GO_DISCOVERY_ON_GKE variable. + stdlog.SetOutput(os.Stdout) + } +} + +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{} +) + +// 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 a new 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) +} + +// logger logs to GCP Stackdriver. +type logger struct { + sdlogger *logging.Logger +} + +func experimentString(ctx context.Context) string { + return strings.Join(experiment.FromContext(ctx).Active(), ", ") +} + +func stackdriverSeverity(s log.Severity) logging.Severity { + switch s { + case log.SeverityDefault: + return logging.Default + case log.SeverityDebug: + return logging.Debug + case log.SeverityInfo: + return logging.Info + case log.SeverityWarning: + return logging.Warning + case log.SeverityError: + return logging.Error + case log.SeverityCritical: + return logging.Critical + default: + panic(fmt.Errorf("unknown severity: %v", s)) + } +} + +func (l *logger) Log(ctx context.Context, s log.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: stackdriverSeverity(s), + Labels: labels, + Payload: payload, + Trace: traceID, + }) +} + +func (l *logger) Flush() { + l.sdlogger.Flush() +} + +var ( + mu sync.Mutex + alreadyCalled bool +) + +// New creates a new Logger that logs to Stackdriver. +// It assumes config.Init has been called. New 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" log.Logger that will +// be used to log within a request. The child logger should be passed to log.Use to +// forward the log package's logging calls to the child logger. +// The two loggers are necessary to get request-scoped logs in Stackdriver. +// See https://cloud.google.com/appengine/docs/standard/go/writing-application-logs. +// +// New can only be called once. If it is called a second time, it returns an error. +func New(ctx context.Context, logName, projectID string, opts []logging.LoggerOption) (_ log.Logger, _ *logging.Logger, err error) { + defer derrors.Wrap(&err, "New(ctx, %q)", logName) + client, err := logging.NewClient(ctx, projectID) + if err != nil { + return nil, nil, err + } + parent := client.Logger(logName, opts...) + child := client.Logger(logName+"-child", opts...) + mu.Lock() + defer mu.Unlock() + if alreadyCalled { + return nil, nil, errors.New("already called once") + } + alreadyCalled = true + return &logger{child}, parent, nil +} diff --git a/internal/middleware/requestlog.go b/internal/middleware/requestlog.go index 2aa948b70..93b42673a 100644 --- a/internal/middleware/requestlog.go +++ b/internal/middleware/requestlog.go @@ -14,6 +14,7 @@ import ( "cloud.google.com/go/logging" "golang.org/x/pkgsite/internal/log" + "golang.org/x/pkgsite/internal/log/stackdriverlogger" ) // Logger is the interface used to write request logs to GCP. @@ -72,7 +73,7 @@ func (h *handler) ServeHTTP(w http.ResponseWriter, r *http.Request) { Trace: traceID, }) w2 := &responseWriter{ResponseWriter: w} - h.delegate.ServeHTTP(w2, r.WithContext(log.NewContextWithTraceID(r.Context(), traceID))) + h.delegate.ServeHTTP(w2, r.WithContext(stackdriverlogger.NewContextWithTraceID(r.Context(), traceID))) s := severity if w2.status == http.StatusServiceUnavailable { // load shedding is a warning, not an error diff --git a/internal/worker/fetch.go b/internal/worker/fetch.go index 14d99ca67..28bfcc8a9 100644 --- a/internal/worker/fetch.go +++ b/internal/worker/fetch.go @@ -29,6 +29,7 @@ import ( "golang.org/x/pkgsite/internal/experiment" "golang.org/x/pkgsite/internal/fetch" "golang.org/x/pkgsite/internal/log" + "golang.org/x/pkgsite/internal/log/stackdriverlogger" "golang.org/x/pkgsite/internal/postgres" "golang.org/x/pkgsite/internal/proxy" "golang.org/x/pkgsite/internal/source" @@ -110,7 +111,7 @@ func (f *Fetcher) FetchAndUpdateState(ctx context.Context, modulePath, requested defer derrors.Wrap(&err, "FetchAndUpdateState(%q, %q, %q)", modulePath, requestedVersion, appVersionLabel) tctx, span := trace.StartSpan(ctx, "FetchAndUpdateState") ctx = experiment.NewContext(tctx, experiment.FromContext(ctx).Active()...) - ctx = log.NewContextWithLabel(ctx, "fetch", modulePath+"@"+requestedVersion) + ctx = stackdriverlogger.NewContextWithLabel(ctx, "fetch", modulePath+"@"+requestedVersion) start := time.Now() var nPackages int64