internal/worker/log: use slog
Use the log/slog package instead of golang.org/x/event.
This removes x/event from the repo.
Until Go 1.22 comes out, use golang.org/x/exp/slog, because
we still test one version back (Go 1.20), and log/slog appeared
in Go 1.21.
Change-Id: Ia0f645069c778741ebb8c359161816a303a2175b
Reviewed-on: https://go-review.googlesource.com/c/vulndb/+/552675
TryBot-Result: Gopher Robot <gobot@golang.org>
LUCI-TryBot-Result: Go LUCI <golang-scoped@luci-project-accounts.iam.gserviceaccount.com>
Run-TryBot: Jonathan Amsterdam <jba@google.com>
Reviewed-by: Tatiana Bradley <tatianabradley@google.com>
diff --git a/cmd/worker/main.go b/cmd/worker/main.go
index 2654f0b..adbf91b 100644
--- a/cmd/worker/main.go
+++ b/cmd/worker/main.go
@@ -20,7 +20,6 @@
"text/tabwriter"
"time"
- "golang.org/x/exp/event"
"golang.org/x/vulndb/internal/cvelistrepo"
"golang.org/x/vulndb/internal/ghsa"
"golang.org/x/vulndb/internal/gitrepo"
@@ -88,8 +87,8 @@
dieWithUsage("%v", err)
}
- ctx := event.WithExporter(context.Background(),
- event.NewExporter(log.NewLineHandler(os.Stderr), nil))
+ ctx := context.Background()
+
if img := os.Getenv("DOCKER_IMAGE"); img != "" {
log.Infof(ctx, "running in docker image %s", img)
}
diff --git a/go.mod b/go.mod
index 6f2b609..d774f3e 100644
--- a/go.mod
+++ b/go.mod
@@ -25,8 +25,7 @@
go.opentelemetry.io/otel v1.21.0
go.opentelemetry.io/otel/sdk v1.21.0
go.opentelemetry.io/otel/trace v1.21.0
- golang.org/x/exp v0.0.0-20231219180239-dc181d75b848
- golang.org/x/exp/event v0.0.0-20231219180239-dc181d75b848
+ golang.org/x/exp v0.0.0-20240103183307-be819d1f06fc
golang.org/x/mod v0.14.0
golang.org/x/oauth2 v0.15.0
golang.org/x/sync v0.5.0
diff --git a/go.sum b/go.sum
index bb34321..f7c0fb1 100644
--- a/go.sum
+++ b/go.sum
@@ -217,8 +217,8 @@
golang.org/x/exp v0.0.0-20190121172915-509febef88a4/go.mod h1:CJ0aWSM057203Lf6IL+f9T1iT9GByDxfZKAQTCR3kQA=
golang.org/x/exp v0.0.0-20231219180239-dc181d75b848 h1:+iq7lrkxmFNBM7xx+Rae2W6uyPfhPeDWD+n+JgppptE=
golang.org/x/exp v0.0.0-20231219180239-dc181d75b848/go.mod h1:iRJReGqOEeBhDZGkGbynYwcHlctCvnjTYIamk7uXpHI=
-golang.org/x/exp/event v0.0.0-20231219180239-dc181d75b848 h1:Fg3nHyeMRa3zOGwrxMfgAYbhOJ6tr/inMof9Eaq4Fgk=
-golang.org/x/exp/event v0.0.0-20231219180239-dc181d75b848/go.mod h1:R4Nj8+ac1oNAVEp6jJGgYrsz0uySlWGocGQ5A74W3DY=
+golang.org/x/exp v0.0.0-20240103183307-be819d1f06fc h1:ao2WRsKSzW6KuUY9IWPwWahcHCgR0s52IfwutMfEbdM=
+golang.org/x/exp v0.0.0-20240103183307-be819d1f06fc/go.mod h1:iRJReGqOEeBhDZGkGbynYwcHlctCvnjTYIamk7uXpHI=
golang.org/x/exp/typeparams v0.0.0-20221208152030-732eee02a75a h1:Jw5wfR+h9mnIYH+OtGT2im5wV1YGGDora5vTv/aa5bE=
golang.org/x/exp/typeparams v0.0.0-20221208152030-732eee02a75a/go.mod h1:AbB0pIl9nAr9wVwH+Z2ZpaocVmF5I4GyWCDIsVjR0bk=
golang.org/x/lint v0.0.0-20181026193005-c67002cb31c3/go.mod h1:UVdnD1Gm6xHRNCYTkRU2/jEulfH38KcIWyp/GAMgvoE=
diff --git a/internal/observe/observe.go b/internal/observe/observe.go
index 19df286..3fa3fe2 100644
--- a/internal/observe/observe.go
+++ b/internal/observe/observe.go
@@ -8,11 +8,12 @@
import (
"context"
+ "golang.org/x/exp/slog"
"net/http"
"strings"
- "golang.org/x/exp/event"
"golang.org/x/vulndb/internal/derrors"
+ "golang.org/x/vulndb/internal/worker/log"
mexporter "github.com/GoogleCloudPlatform/opentelemetry-operations-go/exporter/metric"
texporter "github.com/GoogleCloudPlatform/opentelemetry-operations-go/exporter/trace"
@@ -25,17 +26,13 @@
tnoop "go.opentelemetry.io/otel/trace/noop"
)
-// An Observer handles tracing and metrics exporting.
+// An Observer handles tracing, logging and metrics exporting.
type Observer struct {
ctx context.Context
tracerProvider *sdktrace.TracerProvider
tracer trace.Tracer
propagator propagation.TextMapPropagator
-
- // LogHandlerFunc is invoked in [Observer.Observe] to obtain an
- // [event.Handler] for logging to be added to the [event.Exporter] in
- // addition to the tracing and metrics handlers.
- LogHandlerFunc func(*http.Request) event.Handler
+ baseLogger *slog.Logger
}
// NewObserver creates an Observer.
@@ -77,20 +74,21 @@
gcppropagator.CloudTraceOneWayPropagator{},
propagation.TraceContext{},
propagation.Baggage{}),
+ baseLogger: slog.New(log.NewGoogleCloudHandler(slog.LevelDebug)),
}, nil
}
type key struct{}
+const (
+ traceIDHeader = "X-Cloud-Trace-Context"
+ gcpTraceKey = "logging.googleapis.com/trace"
+)
+
// Observe adds metrics and tracing to an http.Handler.
func (o *Observer) Observe(h http.Handler) http.Handler {
return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
- var otherHandler event.Handler
- if o.LogHandlerFunc != nil {
- otherHandler = o.LogHandlerFunc(r)
- }
- exporter := event.NewExporter(eventHandler{o, otherHandler}, nil)
- ctx := event.WithExporter(r.Context(), exporter)
+ ctx := log.NewContext(r.Context(), o.baseLogger.With(gcpTraceKey, r.Header.Get(traceIDHeader)))
ctx = o.propagator.Extract(ctx, propagation.HeaderCarrier(r.Header))
ctx = context.WithValue(ctx, key{}, o)
defer o.tracerProvider.ForceFlush(o.ctx)
@@ -98,19 +96,6 @@
})
}
-type eventHandler struct {
- o *Observer
- eh event.Handler
-}
-
-// Event implements event.Handler.
-func (h eventHandler) Event(ctx context.Context, ev *event.Event) context.Context {
- if h.eh != nil {
- return h.eh.Event(ctx, ev)
- }
- return ctx
-}
-
func Start(ctx context.Context, name string) (context.Context, trace.Span) {
if obs, ok := ctx.Value(key{}).(*Observer); ok {
return obs.tracer.Start(ctx, name)
diff --git a/internal/worker/log/gcpjson.go b/internal/worker/log/gcpjson.go
deleted file mode 100644
index da45595..0000000
--- a/internal/worker/log/gcpjson.go
+++ /dev/null
@@ -1,86 +0,0 @@
-// Copyright 2021 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
-
-import (
- "context"
- "fmt"
- "io"
- "sync"
- "time"
-
- "golang.org/x/exp/event"
-)
-
-// NewGCPJSONLogger returns a handler which logs events in a format that is
-// understood by Google Cloud Platform logging.
-func NewGCPJSONHandler(w io.Writer, traceID string) event.Handler {
- return &gcpJSONHandler{w: w, traceID: traceID}
-}
-
-type gcpJSONHandler struct {
- traceID string
- mu sync.Mutex // ensure a log line is not interrupted
- w io.Writer
-}
-
-// Event implements event.Handler.Event.
-// It handles Log events and ignores all others.
-// See https://cloud.google.com/logging/docs/agent/logging/configuration#special-fields
-// for treatment of special fields.
-func (h *gcpJSONHandler) Event(ctx context.Context, ev *event.Event) context.Context {
- if ev.Kind != event.LogKind {
- return ctx
- }
- h.mu.Lock()
- defer h.mu.Unlock()
-
- fmt.Fprintf(h.w, `{"time": %q`, ev.At.Format(time.RFC3339))
- if h.traceID != "" {
- fmt.Fprintf(h.w, `, "logging.googleapis.com/trace": %q`, h.traceID)
- }
- gcpLabels := map[string]string{}
- for _, l := range ev.Labels {
- var key string
- switch l.Name {
- case "msg":
- key = "message"
- case "level":
- key = "severity"
- default:
- gcpLabels[l.Name] = l.String() // already quoted, regardless of label kind
- continue
- }
- fmt.Fprintf(h.w, ", %q: ", key)
- switch {
- case !l.HasValue():
- fmt.Fprint(h.w, "null")
- case l.IsInt64():
- fmt.Fprintf(h.w, "%d", l.Int64())
- case l.IsUint64():
- fmt.Fprintf(h.w, "%d", l.Uint64())
- case l.IsFloat64():
- fmt.Fprintf(h.w, "%g", l.Float64())
- case l.IsBool():
- fmt.Fprintf(h.w, "%t", l.Bool())
- default:
- fmt.Fprintf(h.w, "%q", l.String())
- }
- }
- if len(gcpLabels) > 0 {
- fmt.Fprintf(h.w, `, "logging.googleapis.com/labels": {`)
- first := true
- for k, v := range gcpLabels {
- if !first {
- fmt.Fprint(h.w, ", ")
- }
- first = false
- fmt.Fprintf(h.w, "%q: %q", k, v)
- }
- fmt.Fprint(h.w, "}")
- }
- fmt.Fprint(h.w, "}\n")
- return ctx
-}
diff --git a/internal/worker/log/gcpjson_test.go b/internal/worker/log/gcpjson_test.go
deleted file mode 100644
index 2ed5409..0000000
--- a/internal/worker/log/gcpjson_test.go
+++ /dev/null
@@ -1,45 +0,0 @@
-// Copyright 2021 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
-
-import (
- "bytes"
- "context"
- "testing"
- "time"
-
- "golang.org/x/exp/event"
- "golang.org/x/exp/event/severity"
-)
-
-func TestGCPJSON(t *testing.T) {
- now := time.Date(2002, 3, 4, 5, 6, 7, 0, time.UTC)
- for _, test := range []struct {
- ev event.Event
- want string
- }{
- {
- ev: event.Event{
- At: now,
- Kind: event.LogKind,
- Labels: []event.Label{
- event.String("msg", "hello"),
- event.Int64("count", 17),
- severity.Info.Label(),
- },
- },
- want: `{"time": "2002-03-04T05:06:07Z", "logging.googleapis.com/trace": "tid", "message": "hello", "severity": "info", "logging.googleapis.com/labels": {"count": "17"}}
-`,
- },
- } {
- var buf bytes.Buffer
- h := &gcpJSONHandler{w: &buf, traceID: "tid"}
- h.Event(context.Background(), &test.ev)
- got := buf.String()
- if got != test.want {
- t.Errorf("%+v:\ngot %s\nwant %s", test.ev, got, test.want)
- }
- }
-}
diff --git a/internal/worker/log/log.go b/internal/worker/log/log.go
index 2e98142..41e6b01 100644
--- a/internal/worker/log/log.go
+++ b/internal/worker/log/log.go
@@ -8,129 +8,101 @@
import (
"context"
"fmt"
+ "golang.org/x/exp/slog"
"io"
- "reflect"
- "strings"
- "sync"
+ "os"
"time"
-
- "golang.org/x/exp/event"
- "golang.org/x/exp/event/severity"
)
-// NewLineHandler returns an event Handler that writes log events one per line
-// in an easy-to-read format:
-//
-// time level message label1=value1 label2=value2 ...
-func NewLineHandler(w io.Writer) event.Handler {
- return &lineHandler{w: w}
+type Attrs []slog.Attr
+
+func With(args ...any) Attrs {
+ var r slog.Record
+ r.Add(args...)
+ var as Attrs
+ r.Attrs(func(a slog.Attr) bool {
+ as = append(as, a)
+ return true
+ })
+ return as
}
-type lineHandler struct {
- mu sync.Mutex // ensure a log line is not interrupted
- w io.Writer
+func (as Attrs) Debugf(ctx context.Context, format string, args ...interface{}) {
+ as.logf(ctx, slog.LevelDebug, format, args...)
}
-// Event implements event.Handler.Event for log events.
-func (h *lineHandler) Event(ctx context.Context, ev *event.Event) context.Context {
- if ev.Kind != event.LogKind {
- return ctx
- }
- h.mu.Lock()
- defer h.mu.Unlock()
-
- var msg, level string
- var others []string
- for _, lab := range ev.Labels {
- switch lab.Name {
- case "msg":
- msg = lab.String()
- case "level":
- level = strings.ToUpper(lab.String())
- default:
- others = append(others, fmt.Sprintf("%s=%s", lab.Name, lab.String()))
- }
- }
- var s string
- if len(others) > 0 {
- s = " " + strings.Join(others, " ")
- }
- if level != "" {
- level = " " + level
- }
- fmt.Fprintf(h.w, "%s%s %s%s\n", ev.At.Format("2006/01/02 15:04:05"), level, msg, s)
- return ctx
+func (as Attrs) Infof(ctx context.Context, format string, args ...interface{}) {
+ as.logf(ctx, slog.LevelInfo, format, args...)
}
-type Labels []event.Label
-
-func With(kvs ...interface{}) Labels {
- return Labels(nil).With(kvs...)
+func (as Attrs) Warningf(ctx context.Context, format string, args ...interface{}) {
+ as.logf(ctx, slog.LevelWarn, format, args...)
}
-func (ls Labels) With(kvs ...interface{}) Labels {
- if len(kvs)%2 != 0 {
- panic("args must be key-value pairs")
- }
- for i := 0; i < len(kvs); i += 2 {
- ls = append(ls, pairToLabel(kvs[i].(string), kvs[i+1]))
- }
- return ls
-}
-
-func pairToLabel(name string, value interface{}) event.Label {
- if d, ok := value.(time.Duration); ok {
- return event.Duration(name, d)
- }
- v := reflect.ValueOf(value)
- switch v.Kind() {
- case reflect.String:
- return event.String(name, v.String())
- case reflect.Bool:
- return event.Bool(name, v.Bool())
- case reflect.Int, reflect.Int8, reflect.Int16, reflect.Int32, reflect.Int64:
- return event.Int64(name, v.Int())
- case reflect.Uint, reflect.Uint8, reflect.Uint16, reflect.Uint32, reflect.Uint64, reflect.Uintptr:
- return event.Uint64(name, v.Uint())
- case reflect.Float32, reflect.Float64:
- return event.Float64(name, v.Float())
- default:
- return event.Value(name, value)
- }
-}
-
-func (l Labels) logf(ctx context.Context, s severity.Level, format string, args ...interface{}) {
- event.Log(ctx, fmt.Sprintf(format, args...), append(l, s.Label())...)
-}
-
-func (l Labels) Debugf(ctx context.Context, format string, args ...interface{}) {
- l.logf(ctx, severity.Debug, format, args...)
-}
-
-func (l Labels) Infof(ctx context.Context, format string, args ...interface{}) {
- l.logf(ctx, severity.Info, format, args...)
-}
-
-func (l Labels) Warningf(ctx context.Context, format string, args ...interface{}) {
- l.logf(ctx, severity.Warning, format, args...)
-}
-
-func (l Labels) Errorf(ctx context.Context, format string, args ...interface{}) {
- l.logf(ctx, severity.Error, format, args...)
+func (as Attrs) Errorf(ctx context.Context, format string, args ...interface{}) {
+ as.logf(ctx, slog.LevelError, format, args...)
}
func Debugf(ctx context.Context, format string, args ...interface{}) {
- Labels(nil).logf(ctx, severity.Debug, format, args...)
+ Attrs{}.logf(ctx, slog.LevelDebug, format, args...)
}
func Infof(ctx context.Context, format string, args ...interface{}) {
- Labels(nil).logf(ctx, severity.Info, format, args...)
+ Attrs{}.logf(ctx, slog.LevelInfo, format, args...)
}
func Warningf(ctx context.Context, format string, args ...interface{}) {
- Labels(nil).logf(ctx, severity.Warning, format, args...)
+ Attrs{}.logf(ctx, slog.LevelWarn, format, args...)
}
func Errorf(ctx context.Context, format string, args ...interface{}) {
- Labels(nil).logf(ctx, severity.Error, format, args...)
+ Attrs{}.logf(ctx, slog.LevelError, format, args...)
+}
+
+func (as Attrs) logf(ctx context.Context, level slog.Level, format string, args ...interface{}) {
+ FromContext(ctx).LogAttrs(ctx, level, fmt.Sprintf(format, args...), as...)
+}
+
+type key struct{}
+
+func FromContext(ctx context.Context) *slog.Logger {
+ if l, ok := ctx.Value(key{}).(*slog.Logger); ok {
+ return l
+ }
+ return slog.Default()
+}
+
+func NewContext(ctx context.Context, l *slog.Logger) context.Context {
+ return context.WithValue(ctx, key{}, l)
+}
+
+// NewGoogleCloudHandler returns a Handler that outputs JSON for the Google
+// Cloud logging service.
+// See https://cloud.google.com/logging/docs/agent/logging/configuration#special-fields
+// for treatment of special fields.
+func NewGoogleCloudHandler(level slog.Leveler) slog.Handler {
+ return newGoogleCloudHandler(level, os.Stderr)
+}
+
+func newGoogleCloudHandler(level slog.Leveler, w io.Writer) slog.Handler {
+ return slog.NewJSONHandler(w, &slog.HandlerOptions{
+ Level: level,
+ ReplaceAttr: gcpReplaceAttr,
+ })
+}
+
+func gcpReplaceAttr(groups []string, a slog.Attr) slog.Attr {
+ switch a.Key {
+ case "time":
+ if a.Value.Kind() == slog.KindTime {
+ a.Value = slog.StringValue(a.Value.Time().Format(time.RFC3339))
+ }
+ case "msg":
+ a.Key = "message"
+ case "level":
+ a.Key = "severity"
+ case "traceID":
+ a.Key = "logging.googleapis.com/trace"
+ }
+ return a
}
diff --git a/internal/worker/log/log_test.go b/internal/worker/log/log_test.go
new file mode 100644
index 0000000..c97c253
--- /dev/null
+++ b/internal/worker/log/log_test.go
@@ -0,0 +1,42 @@
+// Copyright 2023 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
+
+import (
+ "bytes"
+ "context"
+ "fmt"
+ "golang.org/x/exp/slog"
+ "testing"
+ "time"
+)
+
+// TODO(jba): is it important to put additional attrs under "logging.googleapis.com/labels"?
+
+func TestGoogleCloudHandler(t *testing.T) {
+ var buf bytes.Buffer
+ l := slog.New(newGoogleCloudHandler(slog.LevelInfo, &buf))
+ l = l.With("logging.googleapis.com/trace", "tid")
+ now := time.Now()
+ l.Info("hello", slog.String("foo", "bar"), slog.Int("count", 17))
+ got := buf.String()
+ want := fmt.Sprintf(`{"time":%q,"severity":"INFO","message":"hello","logging.googleapis.com/trace":"tid","foo":"bar","count":17}
+`, now.Format(time.RFC3339))
+ if got != want {
+ t.Errorf("\ngot %s\nwant %s", got, want)
+ }
+
+ buf.Reset()
+ ctx := NewContext(context.Background(), l)
+ now = time.Now()
+ With("a", "b").Warningf(ctx, "hi")
+ got = buf.String()
+ want = fmt.Sprintf(`{"time":%q,"severity":"WARN","message":"hi","logging.googleapis.com/trace":"tid","a":"b"}
+`, now.Format(time.RFC3339))
+ if got != want {
+ t.Errorf("\ngot %s\nwant %s", got, want)
+ }
+
+}
diff --git a/internal/worker/server.go b/internal/worker/server.go
index 6aa2794..ca62ee0 100644
--- a/internal/worker/server.go
+++ b/internal/worker/server.go
@@ -22,7 +22,6 @@
"cloud.google.com/go/errorreporting"
"github.com/google/safehtml/template"
"github.com/jba/metrics"
- "golang.org/x/exp/event"
"golang.org/x/sync/errgroup"
"golang.org/x/vulndb/internal/cvelistrepo"
"golang.org/x/vulndb/internal/derrors"
@@ -52,8 +51,6 @@
observer *observe.Observer
}
-const traceIDHeader = "X-Cloud-Trace-Context"
-
func NewServer(ctx context.Context, cfg Config) (_ *Server, err error) {
defer derrors.Wrap(&err, "NewServer(%q)", cfg.Namespace)
@@ -66,11 +63,6 @@
// This function will be called for each request.
// It lets us install a log handler that knows about the request's
// trace ID.
- s.observer.LogHandlerFunc = func(r *http.Request) event.Handler {
- traceID := r.Header.Get(traceIDHeader)
- return log.NewGCPJSONHandler(os.Stderr, traceID)
- }
-
if cfg.UseErrorReporting {
reportingClient, err := errorreporting.NewClient(ctx, cfg.Project, errorreporting.Config{
ServiceName: serviceID,
diff --git a/internal/worker/worker_test.go b/internal/worker/worker_test.go
index 249ec56..388069c 100644
--- a/internal/worker/worker_test.go
+++ b/internal/worker/worker_test.go
@@ -13,7 +13,6 @@
"fmt"
"math"
"net/http"
- "os"
"sort"
"strings"
"testing"
@@ -21,7 +20,6 @@
"github.com/google/go-cmp/cmp"
"github.com/google/go-cmp/cmp/cmpopts"
- "golang.org/x/exp/event"
"golang.org/x/vulndb/internal/cveschema"
"golang.org/x/vulndb/internal/ghsa"
"golang.org/x/vulndb/internal/gitrepo"
@@ -29,7 +27,6 @@
"golang.org/x/vulndb/internal/issues/githubtest"
"golang.org/x/vulndb/internal/proxy"
"golang.org/x/vulndb/internal/report"
- "golang.org/x/vulndb/internal/worker/log"
"golang.org/x/vulndb/internal/worker/store"
)
@@ -97,8 +94,7 @@
}
func TestCreateIssues(t *testing.T) {
- ctx := event.WithExporter(context.Background(),
- event.NewExporter(log.NewLineHandler(os.Stderr), nil))
+ ctx := context.Background()
mstore := store.NewMemStore()
ic, mux := githubtest.Setup(ctx, t, &issues.Config{
@@ -391,8 +387,7 @@
}
func TestUpdateGHSAs(t *testing.T) {
- ctx := event.WithExporter(context.Background(),
- event.NewExporter(log.NewLineHandler(os.Stderr), nil))
+ ctx := context.Background()
sas := []*ghsa.SecurityAdvisory{
{
ID: "g1",
