feat(cloudslog): initial log/slog primitives

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

* Structured logging of debug.BuildInfo
* 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/handler.go

@@ -0,0 +1,105 @@
+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/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()))
+	}
+	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))
+		}
+	}
+	return attr
+}

cloudslog/handler_test.go

@@ -0,0 +1,18 @@
+package cloudslog
+
+import (
+	"log/slog"
+	"strings"
+	"testing"
+
+	"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"))
+	})
+}

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"`))
+}

cloudslog/proto.go

@@ -0,0 +1,38 @@
+package cloudslog
+
+import (
+	"log/slog"
+
+	"google.golang.org/protobuf/encoding/protojson"
+	"google.golang.org/protobuf/proto"
+)
+
+func newProtoValue(m proto.Message, sizeLimit int) protoValue {
+	return protoValue{Message: m, sizeLimit: sizeLimit}
+}
+
+type protoValue struct {
+	proto.Message
+	sizeLimit int
+}
+
+func (v protoValue) LogValue() slog.Value {
+	if v.sizeLimit > 0 {
+		if size := proto.Size(v.Message); size > v.sizeLimit {
+			return slog.GroupValue(
+				slog.String("message", "truncated due to size"),
+				slog.Int("size", size),
+				slog.Int("limit", v.sizeLimit),
+			)
+		}
+	}
+	return slog.AnyValue(jsonProtoValue{Message: v.Message})
+}
+
+type jsonProtoValue struct {
+	proto.Message
+}
+
+func (v jsonProtoValue) MarshalJSON() ([]byte, error) {
+	return protojson.MarshalOptions{}.Marshal(v.Message)
+}

cloudslog/proto_test.go

@@ -0,0 +1,31 @@
+package cloudslog
+
+import (
+	"log/slog"
+	"strings"
+	"testing"
+
+	"cloud.google.com/go/logging/apiv2/loggingpb"
+	ltype "google.golang.org/genproto/googleapis/logging/type"
+	"gotest.tools/v3/assert"
+)
+
+func TestHandler_proto(t *testing.T) {
+	t.Run("message", func(t *testing.T) {
+		var b strings.Builder
+		logger := slog.New(newHandler(&b, LoggerConfig{}))
+		logger.Info("test", "httpRequest", &ltype.HttpRequest{
+			RequestMethod: "GET",
+		})
+		assert.Assert(t, strings.Contains(b.String(), "requestMethod"))
+	})
+
+	t.Run("enum", func(t *testing.T) {
+		var b strings.Builder
+		logger := slog.New(newHandler(&b, LoggerConfig{}))
+		logger.Info("test", "logEntry", &loggingpb.LogEntry{
+			Severity: ltype.LogSeverity_INFO,
+		})
+		assert.Assert(t, strings.Contains(b.String(), `"severity":"INFO"`))
+	})
+}

cloudslog/redact.go

@@ -0,0 +1,46 @@
+package cloudslog
+
+import (
+	"google.golang.org/protobuf/proto"
+	"google.golang.org/protobuf/reflect/protopath"
+	"google.golang.org/protobuf/reflect/protorange"
+	"google.golang.org/protobuf/reflect/protoreflect"
+	"google.golang.org/protobuf/types/descriptorpb"
+)
+
+func needsRedact(input proto.Message) bool {
+	var result bool
+	_ = protorange.Range(input.ProtoReflect(), func(values protopath.Values) error {
+		last := values.Index(-1)
+		if _, ok := last.Value.Interface().(string); !ok {
+			return nil
+		}
+		if last.Step.Kind() != protopath.FieldAccessStep {
+			return nil
+		}
+		if last.Step.FieldDescriptor().Options().(*descriptorpb.FieldOptions).GetDebugRedact() {
+			result = true
+			return protorange.Terminate
+		}
+		return nil
+	})
+	return result
+}
+
+func redact(input proto.Message) {
+	_ = protorange.Range(input.ProtoReflect(), func(values protopath.Values) error {
+		last := values.Index(-1)
+		if _, ok := last.Value.Interface().(string); !ok {
+			return nil
+		}
+		if last.Step.Kind() != protopath.FieldAccessStep {
+			return nil
+		}
+		if last.Step.FieldDescriptor().Options().(*descriptorpb.FieldOptions).GetDebugRedact() {
+			values.Index(-2).Value.Message().Set(last.Step.FieldDescriptor(), protoreflect.ValueOfString("<redacted>"))
+			return nil
+		}
+		values.Index(-2).Value.Message().Set(last.Step.FieldDescriptor(), protoreflect.ValueOfString("<redacted>"))
+		return nil
+	})
+}