feat: slog context logging (#18)

* implement slog for context based values

Not happy about the aproach :(

* log all request data in the middleware
push id to the context.

* Middle with logger option

* cleanup option naming

* proto type middleware for http client

* attach the logger to context instead

* test the client logger

* take logger from context in client

* return ID as an attribute

* rename EnableHTTPClient for clearer use

* add withgoup option

* finish documentation

* allow group setting for the client
and complete client documentation

* remove clock dependency

.github/workflows/release.yml

@@ -15,7 +15,7 @@ jobs:
     runs-on: ubuntu-22.04
     strategy:
       matrix:
-        go: ['1.17', '1.18', '1.19', '1.20']
+        go: ['1.19', '1.20', '1.21']
     name: Go ${{ matrix.go }} test
     steps:
       - uses: actions/checkout@v3

README.md

@@ -19,11 +19,10 @@ Versions that also build are marked with :warning:.
 
 | Version | Supported          |
 |---------|--------------------|
-| <1.15   | :x:                |
-| 1.15    | :warning:          |
-| 1.16    | :warning:          |
-| 1.17    | :white_check_mark: |
-| 1.18    | :white_check_mark: |
+| <1.19   | :x:                |
+| 1.19    | :warning:          |
+| 1.20    | :white_check_mark: |
+| 1.21    | :white_check_mark: |
 
 ## License
 

attributes.go

@@ -0,0 +1,62 @@
+package logging
+
+import (
+	"fmt"
+	"net/http"
+
+	"golang.org/x/exp/slog"
+)
+
+// StringValuer returns a Valuer that
+// forces the logger to use the type's String
+// method, even in json ouput mode.
+// By wrapping the type we defer String
+// being called to the point we actually log.
+//
+// EXPERIMENTAL: Will change to log/slog import after we drop support for Go 1.20
+func StringerValuer(s fmt.Stringer) slog.LogValuer {
+	return stringerValuer{s}
+}
+
+type stringerValuer struct {
+	fmt.Stringer
+}
+
+func (v stringerValuer) LogValue() slog.Value {
+	return slog.StringValue(v.String())
+}
+
+func requestToAttr(req *http.Request) slog.Attr {
+	return slog.Group("request",
+		slog.String("method", req.Method),
+		slog.Any("url", StringerValuer(req.URL)),
+	)
+}
+
+func responseToAttr(resp *http.Response) slog.Attr {
+	return slog.Group("response",
+		slog.String("status", resp.Status),
+		slog.Int64("content_length", resp.ContentLength),
+	)
+}
+
+// LoggedWriter stores information regarding the response.
+// This might be status code, amount of data written or header.
+//
+// EXPERIMENTAL: Will change to log/slog import after we drop support for Go 1.20
+type LoggedWriter interface {
+	http.ResponseWriter
+
+	// Attr is called after the next handler
+	// in the Middleware returns and
+	// the complete reponse should have been written.
+	//
+	// The returned Attribute should be a [slog.Group]
+	// containing response Attributes.
+	Attr() slog.Attr
+
+	// Err() is called by the middleware to check
+	// if the underlying writer returned an error.
+	// If so, the middleware will print an ERROR line.
+	Err() error
+}

attributes_test.go

@@ -0,0 +1,27 @@
+package logging
+
+import (
+	"net/http/httptest"
+	"testing"
+
+	"github.com/stretchr/testify/assert"
+)
+
+func Test_requestToAttr(t *testing.T) {
+	out, logger := newTestLogger()
+	logger.Info("test", requestToAttr(
+		httptest.NewRequest("GET", "/taget", nil),
+	))
+
+	want := `{
+		"level":"INFO",
+		"msg":"test",
+		"time":"not",
+		"request":{
+			"method":"GET",
+			"url":"/taget"
+		}
+	}`
+	got := out.String()
+	assert.JSONEq(t, want, got)
+}

context.go

@@ -0,0 +1,27 @@
+package logging
+
+import (
+	"context"
+
+	"golang.org/x/exp/slog"
+)
+
+type ctxKeyType struct{}
+
+var ctxKey ctxKeyType
+
+// FromContext takes a Logger from the context, if it was
+// previously set by [ToContext]
+//
+// EXPERIMENTAL: Will change to log/slog import after we drop support for Go 1.20
+func FromContext(ctx context.Context) (logger *slog.Logger, ok bool) {
+	logger, ok = ctx.Value(ctxKey).(*slog.Logger)
+	return logger, ok
+}
+
+// ToContext sets a Logger to the context.
+//
+// EXPERIMENTAL: Will change to log/slog import after we drop support for Go 1.20
+func ToContext(ctx context.Context, logger *slog.Logger) context.Context {
+	return context.WithValue(ctx, ctxKey, logger)
+}

context_test.go

@@ -0,0 +1,21 @@
+package logging
+
+import (
+	"context"
+	"testing"
+
+	"github.com/stretchr/testify/assert"
+	"golang.org/x/exp/slog"
+)
+
+func TestContext(t *testing.T) {
+	got, ok := FromContext(context.Background())
+	assert.False(t, ok)
+	assert.Nil(t, got)
+
+	want := slog.Default()
+	ctx := ToContext(context.Background(), want)
+	got, ok = FromContext(ctx)
+	assert.True(t, ok)
+	assert.Equal(t, want, got)
+}

go.mod

@@ -1,13 +1,19 @@
 module github.com/zitadel/logging
 
-go 1.17
+go 1.19
 
 require (
-	github.com/kr/pretty v0.1.0 // indirect
 	github.com/sirupsen/logrus v1.8.1
-	github.com/stretchr/testify v1.7.0 // indirect
-	golang.org/x/sys v0.1.0 // indirect
-	gopkg.in/check.v1 v1.0.0-20180628173108-788fd7840127 // indirect
+	github.com/stretchr/testify v1.7.0
+	golang.org/x/exp v0.0.0-20230817173708-d852ddb80c63
 	gopkg.in/yaml.v2 v2.2.8
+)
+
+require (
+	github.com/davecgh/go-spew v1.1.1 // indirect
+	github.com/kr/pretty v0.1.0 // indirect
+	github.com/pmezard/go-difflib v1.0.0 // indirect
+	golang.org/x/sys v0.11.0 // indirect
+	gopkg.in/check.v1 v1.0.0-20180628173108-788fd7840127 // indirect
 	gopkg.in/yaml.v3 v3.0.0-20210107192922-496545a6307b // indirect
 )

go.sum

@@ -14,9 +14,11 @@ github.com/stretchr/objx v0.1.0/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+
 github.com/stretchr/testify v1.2.2/go.mod h1:a8OnRcib4nhh0OaRAV+Yts87kKdq0PP7pXfy6kDkUVs=
 github.com/stretchr/testify v1.7.0 h1:nwc3DEeHmmLAfoZucVR881uASk0Mfjw8xYJ99tb5CcY=
 github.com/stretchr/testify v1.7.0/go.mod h1:6Fq8oRcR53rry900zMqJjRRixrwX3KX962/h/Wwjteg=
+golang.org/x/exp v0.0.0-20230817173708-d852ddb80c63 h1:m64FZMko/V45gv0bNmrNYoDEq8U5YUhetc9cBWKS1TQ=
+golang.org/x/exp v0.0.0-20230817173708-d852ddb80c63/go.mod h1:0v4NqG35kSWCMzLaMeX+IQrlSnVE/bqGSyC2cz/9Le8=
 golang.org/x/sys v0.0.0-20191026070338-33540a1f6037/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
-golang.org/x/sys v0.1.0 h1:kunALQeHf1/185U1i0GOB/fy1IPRDDpuoOOqRReG57U=
-golang.org/x/sys v0.1.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
+golang.org/x/sys v0.11.0 h1:eG7RXZHdqOJ1i+0lgLgCpSXAp6M3LYlAo6osgSi0xOM=
+golang.org/x/sys v0.11.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
 gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0=
 gopkg.in/check.v1 v1.0.0-20180628173108-788fd7840127 h1:qIbj1fsPNlZgppZ+VLlY7N33q108Sa+fhmuc+sWQYwY=
 gopkg.in/check.v1 v1.0.0-20180628173108-788fd7840127/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0=

http_client.go

@@ -0,0 +1,113 @@
+package logging
+
+import (
+	"context"
+	"net/http"
+	"time"
+
+	"golang.org/x/exp/slog"
+)
+
+type ClientLoggerOption func(*logRountTripper)
+
+// WithFallbackLogger uses the passed logger if none was
+// found in the context.
+//
+// EXPERIMENTAL: Will change to log/slog import after we drop support for Go 1.20
+func WithFallbackLogger(logger *slog.Logger) ClientLoggerOption {
+	return func(lrt *logRountTripper) {
+		lrt.fallback = logger
+	}
+}
+
+// WithClientDurationFunc allows overiding the request duration
+// for testing.
+func WithClientDurationFunc(df func(time.Time) time.Duration) ClientLoggerOption {
+	return func(lrt *logRountTripper) {
+		lrt.duration = df
+	}
+}
+
+// WithClientGroup groups the log attributes
+// produced by the client.
+func WithClientGroup(name string) ClientLoggerOption {
+	return func(lrt *logRountTripper) {
+		lrt.group = name
+	}
+}
+
+// WithClientRequestAttr allows customizing the information used
+// from a request as request attributes.
+func WithClientRequestAttr(requestToAttr func(*http.Request) slog.Attr) ClientLoggerOption {
+	return func(lrt *logRountTripper) {
+		lrt.reqToAttr = requestToAttr
+	}
+}
+
+// WithClientResponseAttr allows customizing the information used
+// from a response as response attributes.
+func WithClientResponseAttr(responseToAttr func(*http.Response) slog.Attr) ClientLoggerOption {
+	return func(lrt *logRountTripper) {
+		lrt.resToAttr = responseToAttr
+	}
+}
+
+// EnableHTTPClient adds slog functionality to the HTTP client.
+// It attempts to obtain a logger with [FromContext].
+// If no logger is in the context, it tries to use a fallback logger,
+// which might be set by [WithFallbackLogger].
+// If no logger was found finally, the Transport is
+// executed without logging.
+func EnableHTTPClient(c *http.Client, opts ...ClientLoggerOption) {
+	lrt := &logRountTripper{
+		next:      c.Transport,
+		duration:  time.Since,
+		reqToAttr: requestToAttr,
+		resToAttr: responseToAttr,
+	}
+	if lrt.next == nil {
+		lrt.next = http.DefaultTransport
+	}
+	for _, opt := range opts {
+		opt(lrt)
+	}
+	c.Transport = lrt
+}
+
+type logRountTripper struct {
+	next     http.RoundTripper
+	duration func(time.Time) time.Duration
+	fallback *slog.Logger
+
+	group     string
+	reqToAttr func(*http.Request) slog.Attr
+	resToAttr func(*http.Response) slog.Attr
+}
+
+// RoundTrip implements [http.RoundTripper].
+func (l *logRountTripper) RoundTrip(req *http.Request) (*http.Response, error) {
+	logger, ok := l.fromContextOrFallback(req.Context())
+	if !ok {
+		return l.next.RoundTrip(req)
+	}
+	start := time.Now()
+
+	resp, err := l.next.RoundTrip(req)
+	logger = logger.WithGroup(l.group).With(
+		l.reqToAttr(req),
+		slog.Duration("duration", l.duration(start)),
+	)
+	if err != nil {
+		logger.Error("request roundtrip", "error", err)
+		return resp, err
+	}
+	logger.Info("request roundtrip", l.resToAttr(resp))
+	return resp, nil
+}
+
+func (l *logRountTripper) fromContextOrFallback(ctx context.Context) (*slog.Logger, bool) {
+	if logger, ok := FromContext(ctx); ok {
+		return logger, ok
+	}
+	return l.fallback, l.fallback != nil
+}