Enable log/slog from Go v1.21 and migrate scheduler. (#845)

calebbrown · web-flow · commit 94465a12ba06 · 2023-08-29T14:45:30.000+10:00
* Enable slogging and add a way to set slog.Attrs in the context.

Signed-off-by: Caleb Brown &lt;calebbrown@google.com&gt;

* Migrate scheduler of zap logging to slog.

Signed-off-by: Caleb Brown &lt;calebbrown@google.com&gt;

* Bump golang version for the Dockerfiles.

Signed-off-by: Caleb Brown &lt;calebbrown@google.com&gt;

* Bump go version for workflows.

Signed-off-by: Caleb Brown &lt;calebbrown@google.com&gt;

* Add tags to the dockerfile

Signed-off-by: Caleb Brown &lt;calebbrown@google.com&gt;

---------

Signed-off-by: Caleb Brown &lt;calebbrown@google.com&gt;
diff --git a/.github/workflows/build-images.yml b/.github/workflows/build-images.yml
@@ -19,7 +19,7 @@ jobs:
     - name: setup-go
       uses: actions/setup-go@93397bea11091df50f3d7e59dc26a7711a8bcfbe # v4.1.0
       with:
-        go-version: '1.19.1'
+        go-version: '1.21.0'
 
     - name: Enable docker experimental
       run: |
diff --git a/.github/workflows/build.yml b/.github/workflows/build.yml
@@ -13,7 +13,7 @@ jobs:
     - uses: actions/checkout@f43a0e5ff2bd294095638e18286ca9a3d1956744 # v3.6.0
     - uses: actions/setup-go@93397bea11091df50f3d7e59dc26a7711a8bcfbe # v4.1.0
       with:
-        go-version: '1.19.1'
+        go-version: '1.21.0'
     - name: Install libpcap-dev
       run: sudo apt-get install -y libpcap-dev
     - run: go build -o scheduler cmd/scheduler/main.go
diff --git a/.github/workflows/test.yml b/.github/workflows/test.yml
@@ -14,7 +14,7 @@ jobs:
     - uses: actions/checkout@f43a0e5ff2bd294095638e18286ca9a3d1956744 # v3.6.0
     - uses: actions/setup-go@93397bea11091df50f3d7e59dc26a7711a8bcfbe # v4.1.0
       with:
-        go-version: 1.19
+        go-version: '1.21.0'
     - uses: actions/setup-node@5e21ff4d9bc1a8cf6de233a3057d20ec6b3fb69d # v3.8.1
       with:
         node-version: 18
@@ -28,6 +28,6 @@ jobs:
     - uses: actions/checkout@f43a0e5ff2bd294095638e18286ca9a3d1956744 # v3.6.0
     - uses: actions/setup-go@93397bea11091df50f3d7e59dc26a7711a8bcfbe # v4.1.0
       with:
-        go-version: 1.19
+        go-version: '1.21.0'
     - name: golangci-lint
       uses: golangci/golangci-lint-action@3a919529898de77ec3da873e3063ca4b10e7f5cc # v3.7.0
diff --git a/cmd/analyze/Dockerfile b/cmd/analyze/Dockerfile
@@ -1,4 +1,4 @@
-FROM golang@sha256:122f3484f844467ebe0674cf57272e61981770eb0bc7d316d1f0be281a88229f as build
+FROM golang:1.21.0@sha256:12359f96c43077803959dab88ce60c87cd2543f3b907bf54a34a5104270f404f as build
 RUN apt-get update && apt-get install -y libpcap-dev
 WORKDIR /src
 
diff --git a/cmd/scheduler/Dockerfile b/cmd/scheduler/Dockerfile
@@ -1,4 +1,4 @@
-FROM golang@sha256:122f3484f844467ebe0674cf57272e61981770eb0bc7d316d1f0be281a88229f as build
+FROM golang:1.21.0@sha256:12359f96c43077803959dab88ce60c87cd2543f3b907bf54a34a5104270f404f as build
 WORKDIR /src
 
 # First cache the dependencies to avoid downloading again on code change
@@ -7,11 +7,11 @@ COPY ./go.sum ./
 RUN go mod download
 
 COPY . ./
-RUN go build -o scheduler ./cmd/scheduler/main.go
+RUN CGO_ENABLED=0 go build -o scheduler ./cmd/scheduler/main.go
 
 
 FROM gcr.io/distroless/base:nonroot@sha256:bc84925113289d139a9ef2f309f0dd7ac46ea7b786f172ba9084ffdb4cbd9490
 
 COPY --from=build /src/scheduler /usr/local/bin/scheduler
 
-ENTRYPOINT /usr/local/bin/scheduler
+ENTRYPOINT ["/usr/local/bin/scheduler"]
diff --git a/cmd/scheduler/main.go b/cmd/scheduler/main.go
@@ -4,11 +4,11 @@ import (
 	"context"
 	"encoding/json"
 	"fmt"
+	"log/slog"
 	"os"
 	"regexp"
 
 	"github.com/ossf/package-feeds/pkg/feeds"
-	"go.uber.org/zap"
 	"gocloud.dev/pubsub"
 	_ "gocloud.dev/pubsub/gcppubsub"
 	_ "gocloud.dev/pubsub/kafkapubsub"
@@ -60,15 +60,15 @@ var supportedPkgManagers = map[string]*ManagerConfig{
 func main() {
 	subscriptionURL := os.Getenv("OSSMALWARE_SUBSCRIPTION_URL")
 	topicURL := os.Getenv("OSSMALWARE_WORKER_TOPIC")
-	logger := log.Initialize(os.Getenv("LOGGER_ENV")).Desugar()
+	log.Initialize(os.Getenv("LOGGER_ENV")).Desugar()
 
-	err := listenLoop(logger, subscriptionURL, topicURL)
+	err := listenLoop(subscriptionURL, topicURL)
 	if err != nil {
-		logger.With(zap.Error(err)).Error("Error encountered")
+		slog.Error("Error encountered", "error", err)
 	}
 }
 
-func listenLoop(logger *zap.Logger, subURL, topicURL string) error {
+func listenLoop(subURL, topicURL string) error {
 	ctx := context.Background()
 
 	sub, err := pubsub.OpenSubscription(ctx, subURL)
@@ -82,12 +82,10 @@ func listenLoop(logger *zap.Logger, subURL, topicURL string) error {
 	}
 
 	srv := proxy.New(topic, sub)
-	logger.Info("Listening for messages to proxy...")
+	slog.InfoContext(ctx, "Listening for messages to proxy...")
 
-	err = srv.Listen(ctx, logger, func(m *pubsub.Message) (*pubsub.Message, error) {
-		logger.With(
-			zap.ByteString("body", m.Body),
-		).Info("Handling message")
+	err = srv.Listen(ctx, func(m *pubsub.Message) (*pubsub.Message, error) {
+		slog.InfoContext(ctx, "Handling message", "body", string(m.Body))
 		pkg := feeds.Package{}
 		if err := json.Unmarshal(m.Body, &pkg); err != nil {
 			return nil, fmt.Errorf("error unmarshalling json: %w", err)
diff --git a/cmd/scheduler/proxy/proxy.go b/cmd/scheduler/proxy/proxy.go
@@ -2,8 +2,9 @@ package proxy
 
 import (
 	"context"
+	"log/slog"
 
-	"go.uber.org/zap"
+	"github.com/ossf/package-analysis/internal/log"
 	"gocloud.dev/pubsub"
 )
 
@@ -21,29 +22,29 @@ func New(topic *pubsub.Topic, subscription *pubsub.Subscription) *PubSubProxy {
 	}
 }
 
-func (proxy *PubSubProxy) Listen(ctx context.Context, logger *zap.Logger, preprocess MessageMutateFunc) error {
+func (proxy *PubSubProxy) Listen(ctx context.Context, preprocess MessageMutateFunc) error {
 	for {
 		msg, err := proxy.subscription.Receive(ctx)
 		if err != nil {
-			logger.With(zap.Error(err)).Error("Error receiving message")
+			slog.ErrorContext(ctx, "Error receiving message", "error", err)
 			return err
 		}
 		go func(m *pubsub.Message) {
-			logger := logger.With(zap.String("message_id", m.LoggableID))
+			innerCtx := log.ContextWithAttrs(ctx, slog.String("message_id", m.LoggableID))
 			outMsg, err := preprocess(msg)
 			if err != nil {
 				// Failure to parse and process messages should result in an acknowledgement
 				// to avoid the message being redelivered.
-				logger.With(zap.Error(err)).Warn("Error processing message")
+				slog.WarnContext(innerCtx, "Error processing message", "error", err)
 				m.Ack()
 				return
 			}
-			logger.Info("Sending message to topic")
+			slog.InfoContext(innerCtx, "Sending message to topic")
 			if err := proxy.topic.Send(ctx, outMsg); err != nil {
-				logger.With(zap.Error(err)).Error("Error sending message")
+				slog.ErrorContext(ctx, "Error sending message", "error", err)
 				return
 			}
-			logger.Info("Sent message successfully")
+			slog.InfoContext(innerCtx, "Sent message successfully")
 			msg.Ack()
 		}(msg)
 	}
diff --git a/go.mod b/go.mod
@@ -13,7 +13,7 @@ require (
 	go.uber.org/zap v1.25.0
 	gocloud.dev v0.33.1-0.20230808164326-dee61a596af0
 	gocloud.dev/pubsub/kafkapubsub v0.33.0
-	golang.org/x/exp v0.0.0-20230321023759-10a507213a29
+	golang.org/x/exp v0.0.0-20230425010034-47ecfdc1ba53
 	google.golang.org/api v0.138.0
 	google.golang.org/grpc v1.57.0
 	google.golang.org/protobuf v1.31.0
@@ -84,6 +84,7 @@ require (
 	github.com/zeebo/xxh3 v1.0.2 // indirect
 	go.opencensus.io v0.24.0 // indirect
 	go.uber.org/multierr v1.11.0 // indirect
+	go.uber.org/zap/exp v0.1.1-0.20230825131617-98e9c4fe632c // indirect
 	golang.org/x/crypto v0.12.0 // indirect
 	golang.org/x/mod v0.10.0 // indirect
 	golang.org/x/net v0.14.0 // indirect
diff --git a/go.sum b/go.sum
@@ -459,6 +459,10 @@ go.uber.org/multierr v1.11.0/go.mod h1:20+QtiLqy0Nd6FdQB9TLXag12DsQkrbs3htMFfDN8
 go.uber.org/zap v1.10.0/go.mod h1:vwi/ZaCAaUcBkycHslxD9B2zi4UTXhF60s6SWpuDF0Q=
 go.uber.org/zap v1.25.0 h1:4Hvk6GtkucQ790dqmj7l1eEnRdKm3k3ZUrUMS2d5+5c=
 go.uber.org/zap v1.25.0/go.mod h1:JIAUzQIH94IC4fOJQm7gMmBJP5k7wQfdcnYdPoEXJYk=
+go.uber.org/zap/exp v0.1.0 h1:Ol9zQNvAEAgFHSBiR5LlwS9Xq8u5QF+7HBwNHUB8rcI=
+go.uber.org/zap/exp v0.1.0/go.mod h1:z/0T3As39ttolxZGOsvk1OEvQfwwfTZpmV9YTp+VAkc=
+go.uber.org/zap/exp v0.1.1-0.20230825131617-98e9c4fe632c h1:GIiV03MzB73EsQ7Hj8et4lHV+98RplF4tLznIqsmeIc=
+go.uber.org/zap/exp v0.1.1-0.20230825131617-98e9c4fe632c/go.mod h1:t0gqAIdh1MfKv9EwN/dLwfZnJxe9ITAZN78HEWPFWDQ=
 gocloud.dev v0.22.0/go.mod h1:z3jKIQ0Es9LALVZFQ3wOvwqAsSLq1R5c/2RdmghDucw=
 gocloud.dev v0.33.1-0.20230808164326-dee61a596af0 h1://FYsd3KnVdEJOVT6JaWvAKvUjvKnDnnovQnuwc33Ec=
 gocloud.dev v0.33.1-0.20230808164326-dee61a596af0/go.mod h1:z6W8qorjrfM09H8t1MDk8KLPj3Xi26aFBzDKAHWIgLU=
@@ -492,6 +496,8 @@ golang.org/x/exp v0.0.0-20200207192155-f17229e696bd/go.mod h1:J/WKrq2StrnmMY6+EH
 golang.org/x/exp v0.0.0-20200224162631-6cc2880d07d6/go.mod h1:3jZMyOhIsHpP37uCMkUooju7aAi5cS1Q23tOzKc+0MU=
 golang.org/x/exp v0.0.0-20230321023759-10a507213a29 h1:ooxPy7fPvB4kwsA2h+iBNHkAbp/4JxTSwCmvdjEYmug=
 golang.org/x/exp v0.0.0-20230321023759-10a507213a29/go.mod h1:CxIveKay+FTh1D0yPZemJVgC/95VzuuOLq5Qi4xnoYc=
+golang.org/x/exp v0.0.0-20230425010034-47ecfdc1ba53 h1:5llv2sWeaMSnA3w2kS57ouQQ4pudlXrR0dCgw51QK9o=
+golang.org/x/exp v0.0.0-20230425010034-47ecfdc1ba53/go.mod h1:V1LtkGg67GoY2N1AnLN78QLrzxkLyJw7RJb1gzOOz9w=
 golang.org/x/image v0.0.0-20190227222117-0694c2d4d067/go.mod h1:kZ7UVZpmo3dzQBMxlp+ypCbDeSB+sBbTgSJuh5dn5js=
 golang.org/x/image v0.0.0-20190802002840-cff245a6509b/go.mod h1:FeLwcggjj3mMvU+oOTbSwawSJRM1uh48EjtB4UJZlP0=
 golang.org/x/lint v0.0.0-20181026193005-c67002cb31c3/go.mod h1:UVdnD1Gm6xHRNCYTkRU2/jEulfH38KcIWyp/GAMgvoE=
diff --git a/internal/log/context.go b/internal/log/context.go
@@ -0,0 +1,46 @@
+package log
+
+import (
+	"context"
+	"log/slog"
+)
+
+var contextAttrSliceKey = struct{}{}
+
+func attrSliceFromContext(ctx context.Context) []slog.Attr {
+	if v := ctx.Value(contextAttrSliceKey); v != nil {
+		return v.([]slog.Attr)
+	}
+	return nil
+}
+
+// ContextWithAttrs is used to add attrs to the context so they are included
+// when logs are output.
+func ContextWithAttrs(ctx context.Context, attr ...slog.Attr) context.Context {
+	if len(attr) == 0 {
+		return ctx
+	}
+	attrSlice := attrSliceFromContext(ctx)
+	attrSlice = append(attrSlice, attr...)
+	return context.WithValue(ctx, contextAttrSliceKey, attrSlice)
+}
+
+type contextLogHandler struct {
+	slog.Handler
+}
+
+func (h *contextLogHandler) Handle(ctx context.Context, r slog.Record) error {
+	attrSlice := attrSliceFromContext(ctx)
+	if attrSlice != nil {
+		r.AddAttrs(attrSlice...)
+	}
+	return h.Handler.Handle(ctx, r)
+}
+
+// NewContextLogHandler returns a new slog.Handler that will pass the attrs set
+// using ContextWithAttrs to handler when Handle is called.
+func NewContextLogHandler(handler slog.Handler) slog.Handler {
+	return &contextLogHandler{
+		Handler: handler,
+	}
+}
diff --git a/internal/log/context_test.go b/internal/log/context_test.go
@@ -0,0 +1,108 @@
+package log_test
+
+import (
+	"context"
+	"testing"
+
+	"log/slog"
+
+	"github.com/ossf/package-analysis/internal/log"
+)
+
+type testHandler struct {
+	slog.Handler
+
+	r slog.Record
+}
+
+func (h *testHandler) Enabled(_ context.Context, _ slog.Level) bool {
+	return true
+}
+
+func (h *testHandler) Handle(ctx context.Context, r slog.Record) error {
+	h.r = r
+	return nil
+}
+
+func assertRecordAttrs(t *testing.T, r slog.Record, attrs []slog.Attr) {
+	t.Helper()
+
+	wantLen := len(attrs)
+	gotLen := r.NumAttrs()
+	if wantLen != gotLen {
+		t.Errorf("record.NumAttrs() = %v; want %v", gotLen, wantLen)
+	}
+
+	r.Attrs(func(a slog.Attr) bool {
+		for _, attr := range attrs {
+			if a.Equal(attr) {
+				return true
+			}
+		}
+		t.Errorf("unexpected attr %v", a)
+		return true
+	})
+}
+
+func TestContextWithAttrs(t *testing.T) {
+	attr1 := slog.Any("hello", "world")
+	attr2 := slog.Int("meaning", 42)
+	attr3 := slog.String("a", "b")
+
+	h := &testHandler{}
+	logger := slog.New(log.NewContextLogHandler(h))
+
+	ctx := context.Background()
+
+	// Add attrs to the context and ensure they are used.
+	ctx = log.ContextWithAttrs(ctx, attr1, attr2)
+	logger.InfoContext(ctx, "test", "a", "b")
+	assertRecordAttrs(t, h.r, []slog.Attr{attr1, attr2, attr3})
+}
+
+func TestContextWithAttrs_InnerCtx(t *testing.T) {
+	attr1 := slog.Any("hello", "world")
+	attr2 := slog.Int("meaning", 42)
+	attr3 := slog.Any("complex", struct{ a string }{a: "string"})
+
+	h := &testHandler{}
+	logger := slog.New(log.NewContextLogHandler(h))
+
+	ctx := context.Background()
+	ctx = log.ContextWithAttrs(ctx, attr1, attr2)
+
+	// Add more attrs to the context and ensure they are used.
+	innerCtx := log.ContextWithAttrs(ctx, attr3)
+	logger.InfoContext(innerCtx, "test")
+	assertRecordAttrs(t, h.r, []slog.Attr{attr1, attr2, attr3})
+}
+
+func TestContextWithAttrs_OuterAfterInnerCtx(t *testing.T) {
+	attr1 := slog.Any("hello", "world")
+	attr2 := slog.Int("meaning", 42)
+	attr3 := slog.Any("complex", struct{ a string }{a: "string"})
+
+	h := &testHandler{}
+	logger := slog.New(log.NewContextLogHandler(h))
+
+	ctx := context.Background()
+	ctx = log.ContextWithAttrs(ctx, attr1, attr2)
+	_ = log.ContextWithAttrs(ctx, attr3)
+
+	// Use the earlier context to ensure the innerCtx attrs are not included.
+	logger.InfoContext(ctx, "test")
+	assertRecordAttrs(t, h.r, []slog.Attr{attr1, attr2})
+}
+
+func TestContextWithAttrs_NoAttrs(t *testing.T) {
+	attr1 := slog.String("a", "b")
+
+	h := &testHandler{}
+	logger := slog.New(log.NewContextLogHandler(h))
+
+	ctx := context.Background()
+	ctx = log.ContextWithAttrs(ctx)
+
+	logger.InfoContext(ctx, "test", "a", "b")
+	assertRecordAttrs(t, h.r, []slog.Attr{attr1})
+}
diff --git a/internal/log/log.go b/internal/log/log.go
@@ -9,10 +9,12 @@ package log
 
 import (
 	golog "log"
+	"log/slog"
 	"strings"
 
 	"github.com/blendle/zapdriver"
 	"go.uber.org/zap"
+	"go.uber.org/zap/exp/zapslog"
 	"go.uber.org/zap/zapcore"
 )
 
@@ -84,6 +86,12 @@ func Initialize(env string) *zap.SugaredLogger {
 		golog.Panic(err)
 	}
 	zap.RedirectStdLog(logger)
+	// Ensure slog.Default logs to the same destination as zap.
+	slogger := slog.New(NewContextLogHandler(zapslog.NewHandler(logger.Core(), &zapslog.HandlerOptions{
+		AddSource: true,
+	})))
+	slog.SetDefault(slogger)
+
 	logger = logger.WithOptions(zap.AddCallerSkip(1))
 	defaultLogger = logger.Sugar() // Set defaultLogger to provide legacy support
 	return defaultLogger
diff --git a/sandboxes/staticanalysis/Dockerfile b/sandboxes/staticanalysis/Dockerfile
@@ -1,4 +1,4 @@
-FROM golang:1.19-alpine@sha256:122f3484f844467ebe0674cf57272e61981770eb0bc7d316d1f0be281a88229f as build
+FROM golang:1.21.0@sha256:12359f96c43077803959dab88ce60c87cd2543f3b907bf54a34a5104270f404f as build
 
 # Note: Dockerfile uses paths relative to the top-level project directory,
 # so it should be built from that directory, i.e:

Original file line number	Diff line number	Diff line change
`@@ -1,4 +1,4 @@`
`1`		`-FROM golang@sha256:122f3484f844467ebe0674cf57272e61981770eb0bc7d316d1f0be281a88229f as build`
	`1`	`+FROM golang:1.21.0@sha256:12359f96c43077803959dab88ce60c87cd2543f3b907bf54a34a5104270f404f as build`
`2`	`2`	`RUN apt-get update && apt-get install -y libpcap-dev`
`3`	`3`	`WORKDIR /src`
`4`	`4`