feat(cloudslog): initial log/slog primitives

Aiming for feature-parity with current Zap-based logger:

* Structured logging of debug.BuildInfo
* Attributes propagated in context.Context
* Patching the UTF-8 bug in ltype.HttpRequest
* Proto messages logged as JSON
* Size limit for proto messages
* Redaction of sensitive fields in proto messages
* Structured logging of OpenTelemetry resource descriptors

Goal is to make this the default logger for request logging and other
logging in this library.

.sage/main.go

@@ -27,7 +27,8 @@ func main() {
 }
 
 func All(ctx context.Context) error {
-	sg.Deps(ctx, ConvcoCheck, GoLint, GoTest, FormatMarkdown, FormatYAML, ReadmeSnippet)
+	sg.Deps(ctx, ConvcoCheck, FormatMarkdown, FormatYAML, ReadmeSnippet)
+	sg.Deps(ctx, GoLint, GoTest)
 	sg.Deps(ctx, GoModTidy)
 	sg.Deps(ctx, GitVerifyNoDiff)
 	return nil
@@ -53,6 +54,11 @@ func GoLint(ctx context.Context) error {
 	return sggolangcilint.Run(ctx)
 }
 
+func GoLintFix(ctx context.Context) error {
+	sg.Logger(ctx).Println("fixing Go files...")
+	return sggolangcilint.Fix(ctx)
+}
+
 // TODO: Add this to All target once it is working again.
 func GoLicenses(ctx context.Context) error {
 	sg.Logger(ctx).Println("checking Go licenses...")

Makefile

@@ -71,6 +71,10 @@ go-licenses: $(sagefile)
 go-lint: $(sagefile)
 	@$(sagefile) GoLint
 
+.PHONY: go-lint-fix
+go-lint-fix: $(sagefile)
+	@$(sagefile) GoLintFix
+
 .PHONY: go-mod-tidy
 go-mod-tidy: $(sagefile)
 	@$(sagefile) GoModTidy

cloudslog/buildinfo.go

@@ -0,0 +1,26 @@
+package cloudslog
+
+import (
+	"log/slog"
+	"runtime/debug"
+)
+
+func newBuildInfoValue(bi *debug.BuildInfo) buildInfoValue {
+	return buildInfoValue{BuildInfo: bi}
+}
+
+type buildInfoValue struct {
+	*debug.BuildInfo
+}
+
+func (v buildInfoValue) LogValue() slog.Value {
+	buildSettings := make([]any, 0, len(v.Settings))
+	for _, setting := range v.BuildInfo.Settings {
+		buildSettings = append(buildSettings, slog.String(setting.Key, setting.Value))
+	}
+	return slog.GroupValue(
+		slog.String("mainPath", v.BuildInfo.Main.Path),
+		slog.String("goVersion", v.BuildInfo.GoVersion),
+		slog.Group("buildSettings", buildSettings...),
+	)
+}

cloudslog/buildinfo_test.go

@@ -0,0 +1,20 @@
+package cloudslog
+
+import (
+	"log/slog"
+	"runtime/debug"
+	"strings"
+	"testing"
+
+	"gotest.tools/v3/assert"
+)
+
+func TestHandler_buildInfoValue(t *testing.T) {
+	var b strings.Builder
+	logger := slog.New(newHandler(&b, LoggerConfig{}))
+	buildInfo, ok := debug.ReadBuildInfo()
+	assert.Assert(t, ok)
+	logger.Info("test", "buildInfo", buildInfo)
+	t.Log(b.String())
+	assert.Assert(t, strings.Contains(b.String(), `"buildInfo":{"mainPath":`))
+}

cloudslog/context.go

@@ -0,0 +1,61 @@
+package cloudslog
+
+import (
+	"context"
+	"log/slog"
+	"sync"
+)
+
+type contextKey struct{}
+
+type contextValue struct {
+	mu     sync.Mutex
+	attrs  []slog.Attr
+	arrays []*arrayValue
+}
+
+type arrayValue struct {
+	key    string
+	values []any
+}
+
+// WithAttributes attaches attaches log attributes to the returned child context.
+func WithAttributes(ctx context.Context, attrs ...slog.Attr) context.Context {
+	ctxValue, ok := ctx.Value(contextKey{}).(*contextValue)
+	if !ok {
+		ctxValue = &contextValue{}
+		ctx = context.WithValue(ctx, contextKey{}, ctxValue)
+	}
+	ctxValue.mu.Lock()
+	defer ctxValue.mu.Unlock()
+	ctxValue.attrs = append(ctxValue.attrs, attrs...)
+	return ctx
+}
+
+// WithAppendValues appends repeated log fields to the specified key in the returned child context.
+func WithAppendValues(ctx context.Context, key string, values ...slog.Value) context.Context {
+	ctxValue, ok := ctx.Value(contextKey{}).(*contextValue)
+	if !ok {
+		ctxValue = &contextValue{}
+		ctx = context.WithValue(ctx, contextKey{}, ctxValue)
+	}
+	ctxValue.mu.Lock()
+	defer ctxValue.mu.Unlock()
+	var array *arrayValue
+	for _, needle := range ctxValue.arrays {
+		if needle.key == key {
+			array = needle
+			break
+		}
+	}
+	if array == nil {
+		array = &arrayValue{
+			key: key,
+		}
+		ctxValue.arrays = append(ctxValue.arrays, array)
+	}
+	for _, value := range values {
+		array.values = append(array.values, value.Any())
+	}
+	return ctx
+}

cloudslog/context_test.go

@@ -0,0 +1,30 @@
+package cloudslog
+
+import (
+	"context"
+	"log/slog"
+	"strings"
+	"testing"
+
+	"gotest.tools/v3/assert"
+)
+
+func TestHandler_withAttributes(t *testing.T) {
+	ctx := context.Background()
+	var b strings.Builder
+	logger := slog.New(newHandler(&b, LoggerConfig{}))
+	ctx = WithAttributes(ctx, slog.String("foo", "bar"))
+	logger.InfoContext(ctx, "test")
+	assert.Assert(t, strings.Contains(b.String(), `"foo":"bar"`))
+}
+
+func TestHandler_withAppendValues(t *testing.T) {
+	ctx := context.Background()
+	var b strings.Builder
+	logger := slog.New(newHandler(&b, LoggerConfig{}))
+	ctx = WithAppendValues(ctx, "foo", slog.StringValue("bar"))
+	ctx = WithAppendValues(ctx, "foo", slog.StringValue("baz"))
+	logger.InfoContext(ctx, "test")
+	t.Log(b.String())
+	assert.Assert(t, strings.Contains(b.String(), `"foo":["bar","baz"]`))
+}

cloudslog/handler.go

@@ -0,0 +1,118 @@
+package cloudslog
+
+import (
+	"context"
+	"io"
+	"log/slog"
+	"os"
+	"runtime/debug"
+
+	"go.opentelemetry.io/otel/sdk/resource"
+	"go.opentelemetry.io/otel/trace"
+	ltype "google.golang.org/genproto/googleapis/logging/type"
+	"google.golang.org/grpc/status"
+	"google.golang.org/protobuf/proto"
+)
+
+// LoggerConfig configures the application logger.
+type LoggerConfig struct {
+	// Development indicates if the logger should output human-readable output for development.
+	Development bool `default:"true" onGCE:"false"`
+	// Level indicates which log level the logger should output at.
+	Level slog.Level `default:"debug" onGCE:"info"`
+	// ProtoMessageSizeLimit is the maximum size, in bytes, of requests and responses to log.
+	// Messages large than the limit will be truncated.
+	// Default value, 0, means that no messages will be truncated.
+	ProtoMessageSizeLimit int `onGCE:"1024"`
+}
+
+// NewHandler creates a new [slog.Handler] with special-handling for Cloud Run.
+func NewHandler(config LoggerConfig) slog.Handler {
+	return newHandler(os.Stdout, config)
+}
+
+func newHandler(w io.Writer, config LoggerConfig) slog.Handler {
+	replacer := &attrReplacer{config: config}
+	var result slog.Handler
+	if config.Development {
+		result = slog.NewTextHandler(w, &slog.HandlerOptions{
+			Level:       config.Level,
+			ReplaceAttr: replacer.replaceAttr,
+		})
+	} else {
+		result = slog.NewJSONHandler(w, &slog.HandlerOptions{
+			AddSource:   true,
+			Level:       config.Level,
+			ReplaceAttr: replacer.replaceAttr,
+		})
+	}
+	result = &handler{Handler: result}
+	return result
+}
+
+type handler struct {
+	slog.Handler
+}
+
+var _ slog.Handler = &handler{}
+
+// Handle adds attributes from the span context to the [slog.Record].
+func (t *handler) Handle(ctx context.Context, record slog.Record) error {
+	if s := trace.SpanContextFromContext(ctx); s.IsValid() {
+		// See: https://cloud.google.com/logging/docs/structured-logging#special-payload-fields
+		record.AddAttrs(slog.Any("logging.googleapis.com/trace", s.TraceID()))
+		record.AddAttrs(slog.Any("logging.googleapis.com/spanId", s.SpanID()))
+		record.AddAttrs(slog.Bool("logging.googleapis.com/trace_sampled", s.TraceFlags().IsSampled()))
+	}
+	if value, ok := ctx.Value(contextKey{}).(*contextValue); ok {
+		value.mu.Lock()
+		record.AddAttrs(value.attrs...)
+		for _, array := range value.arrays {
+			record.AddAttrs(slog.Any(array.key, array.values))
+		}
+		value.mu.Unlock()
+	}
+	return t.Handler.Handle(ctx, record)
+}
+
+type attrReplacer struct {
+	config LoggerConfig
+}
+
+func (r *attrReplacer) replaceAttr(_ []string, attr slog.Attr) slog.Attr {
+	switch attr.Key {
+	case slog.LevelKey:
+		// See: https://cloud.google.com/logging/docs/reference/v2/rest/v2/LogEntry#LogSeverity
+		attr.Key = "severity"
+		if level := attr.Value.Any().(slog.Level); level == slog.LevelWarn {
+			attr.Value = slog.StringValue("WARNING")
+		}
+	case slog.TimeKey:
+		attr.Key = "timestamp"
+	case slog.MessageKey:
+		attr.Key = "message"
+	case slog.SourceKey:
+		attr.Key = "logging.googleapis.com/sourceLocation"
+	}
+	if attr.Value.Kind() == slog.KindAny {
+		switch value := attr.Value.Any().(type) {
+		case *resource.Resource:
+			attr.Value = slog.AnyValue(newResourceValue(value))
+		case *debug.BuildInfo:
+			attr.Value = slog.AnyValue(newBuildInfoValue(value))
+		case *ltype.HttpRequest:
+			attr.Value = slog.AnyValue(newProtoValue(fixHTTPRequest(value), r.config.ProtoMessageSizeLimit))
+		case proto.Message:
+			if needsRedact(value) {
+				value = proto.Clone(value)
+				redact(value)
+			}
+			attr.Value = slog.AnyValue(newProtoValue(value, r.config.ProtoMessageSizeLimit))
+		case error:
+			if s, ok := status.FromError(value); ok {
+				attr.Value = slog.AnyValue(newProtoValue(s.Proto(), r.config.ProtoMessageSizeLimit))
+			}
+		}
+	}
+	return attr
+}

cloudslog/handler_test.go

@@ -0,0 +1,38 @@
+package cloudslog
+
+import (
+	"log/slog"
+	"strings"
+	"testing"
+
+	"google.golang.org/genproto/googleapis/rpc/errdetails"
+	"google.golang.org/grpc/codes"
+	"google.golang.org/grpc/status"
+	"gotest.tools/v3/assert"
+)
+
+func TestHandler(t *testing.T) {
+	t.Run("source", func(t *testing.T) {
+		var b strings.Builder
+		logger := slog.New(newHandler(&b, LoggerConfig{}))
+		logger.Info("test")
+		assert.Assert(t, strings.Contains(b.String(), "logging.googleapis.com/sourceLocation"))
+	})
+
+	t.Run("error details", func(t *testing.T) {
+		var b strings.Builder
+		logger := slog.New(newHandler(&b, LoggerConfig{}))
+		st, err := status.New(codes.Internal, "example error").WithDetails(&errdetails.BadRequest{
+			FieldViolations: []*errdetails.BadRequest_FieldViolation{
+				{
+					Field:       "foo",
+					Description: "bar",
+				},
+			},
+		})
+		assert.NilError(t, err)
+		logger.Error("test", "error", st.Err())
+		t.Log(b.String())
+		assert.Assert(t, strings.Contains(b.String(), `"field":"foo","description":"bar"`))
+	})
+}

cloudslog/httprequest.go

@@ -0,0 +1,39 @@
+package cloudslog
+
+import (
+	"bytes"
+	"unicode/utf8"
+
+	ltype "google.golang.org/genproto/googleapis/logging/type"
+	"google.golang.org/protobuf/proto"
+)
+
+func fixHTTPRequest(r *ltype.HttpRequest) *ltype.HttpRequest {
+	// Fix issue with invalid UTF-8.
+	// See: https://github.com/googleapis/google-cloud-go/issues/1383.
+	if fixedRequestURL := fixUTF8(r.GetRequestUrl()); fixedRequestURL != r.GetRequestUrl() {
+		r = proto.Clone(r).(*ltype.HttpRequest)
+		r.RequestUrl = fixedRequestURL
+	}
+	return r
+}
+
+// fixUTF8 is a helper that fixes an invalid UTF-8 string by replacing
+// invalid UTF-8 runes with the Unicode replacement character (U+FFFD).
+// See: https://github.com/googleapis/google-cloud-go/issues/1383.
+func fixUTF8(s string) string {
+	if utf8.ValidString(s) {
+		return s
+	}
+	// Otherwise time to build the sequence.
+	buf := new(bytes.Buffer)
+	buf.Grow(len(s))
+	for _, r := range s {
+		if utf8.ValidRune(r) {
+			buf.WriteRune(r)
+		} else {
+			buf.WriteRune('\uFFFD')
+		}
+	}
+	return buf.String()
+}

cloudslog/httprequest_test.go

@@ -0,0 +1,20 @@
+package cloudslog
+
+import (
+	"log/slog"
+	"strings"
+	"testing"
+
+	ltype "google.golang.org/genproto/googleapis/logging/type"
+	"gotest.tools/v3/assert"
+)
+
+func TestHandler_httpRequest(t *testing.T) {
+	var b strings.Builder
+	logger := slog.New(newHandler(&b, LoggerConfig{}))
+	logger.Info("test", "httpRequest", &ltype.HttpRequest{
+		RequestMethod: "GET",
+		RequestUrl:    "/foo/bar",
+	})
+	assert.Assert(t, strings.Contains(b.String(), `"requestUrl":"/foo/bar"`))
+}