Merge pull request #21 from veqryn/http-middleware

Http middleware

README.md

@@ -26,10 +26,17 @@ whenever a new log line is written.
 
 In that same workflow, the `HandlerOptions` and `AttrExtractor` types let us
 extract any custom values from a context and have them automatically be
-prepended or appended to all log lines using that context. For example, the
-`slogotel.ExtractTraceSpanID` extractor will automatically extract the OTEL
+prepended or appended to all log lines using that context. By default, there are
+extractors for anything added via `Prepend` and `Append`, but this repository
+contains some optional Extractors that can be added:
+* `slogotel.ExtractTraceSpanID` extractor will automatically extract the OTEL
 (OpenTelemetry) TraceID and SpanID, and add them to the log record, while also
 annotating the Span with an error code if the log is at error level.
+* `sloghttp.ExtractAttrCollection` extractor will automatically add to the log
+record any attributes added by `sloghttp.With` after the `sloghttp.AttrCollection`
+http middleware. This allows other middlewares to log with attributes that would
+normally be out of scope, because they were added by a later middleware or the
+final http handler in the chain.
 
 #### Logger in Context Workflow:
 
@@ -68,6 +75,7 @@ import (
 ```
 
 ## Usage
+[Examples in repo](examples/)
 ### Logger in Context Workflow
 ```go
 package main
@@ -443,6 +451,123 @@ func newTraceProvider(exp sdktrace.SpanExporter) *sdktrace.TracerProvider {
 }
 ```
 
+#### Slog Attribute Collection HTTP Middleware and Extractor
+```go
+package main
+
+import (
+	"log/slog"
+	"net/http"
+	"os"
+
+	slogctx "github.com/veqryn/slog-context"
+	sloghttp "github.com/veqryn/slog-context/http"
+)
+
+func init() {
+	// Create the *slogctx.Handler middleware
+	h := slogctx.NewHandler(
+		slog.NewJSONHandler(os.Stdout, nil), // The next or final handler in the chain
+		&slogctx.HandlerOptions{
+			// Prependers will first add the any sloghttp.With attributes,
+			// then anything else Prepended to the ctx
+			Prependers: []slogctx.AttrExtractor{
+				sloghttp.ExtractAttrCollection, // our sloghttp middleware extractor
+				slogctx.ExtractPrepended,       // for all other prepended attributes
+			},
+		},
+	)
+	slog.SetDefault(slog.New(h))
+}
+
+func main() {
+	slog.Info("Starting server. Please run: curl localhost:8080/hello?id=24680")
+
+	// Wrap our final handler inside our middlewares.
+	// AttrCollector -> Request Logging -> Final Endpoint Handler (helloUser)
+	handler := sloghttp.AttrCollection(
+		httpLoggingMiddleware(
+			http.HandlerFunc(helloUser),
+		),
+	)
+
+	// Demonstrate the sloghttp middleware with a http server
+	http.Handle("/hello", handler)
+	err := http.ListenAndServe(":8080", nil)
+	if err != nil {
+		panic(err)
+	}
+}
+
+// This is a stand-in for a middleware that might be capturing and logging out
+// things like the response code, request body, response body, url, method, etc.
+// It doesn't have access to any of the new context objects's created within the
+// next handler. But it should still log with any of the attributes added to our
+// sloghttp.Middleware, via sloghttp.With.
+func httpLoggingMiddleware(next http.Handler) http.Handler {
+	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+		// Add some logging context/baggage before the handler
+		r = r.WithContext(sloghttp.With(r.Context(), "path", r.URL.Path))
+
+		// Call the next handler
+		next.ServeHTTP(w, r)
+
+		// Log out that we had a response. This would be where we could add
+		// things such as the response status code, body, etc.
+
+		// Should also have both "path" and "id", but not "foo".
+		// Having "id" included in the log is the whole point of this package!
+		slogctx.Info(r.Context(), "Response", "method", r.Method)
+		/*
+			{
+				"time": "2024-04-01T00:06:11Z",
+				"level": "INFO",
+				"msg": "Response",
+				"path": "/hello",
+				"id": "24680",
+				"method": "GET"
+			}
+		*/
+	})
+}
+
+// This is our final api endpoint handler
+func helloUser(w http.ResponseWriter, r *http.Request) {
+	// Stand-in for a User ID.
+	// Add it to our middleware's context
+	id := r.URL.Query().Get("id")
+
+	// sloghttp.With will add the "id" to to the middleware, because it is a
+	// synchronized map. It will show up in all log calls up and down the stack,
+	// until the request sloghttp middleware exits.
+	ctx := sloghttp.With(r.Context(), "id", id)
+
+	// The regular slogctx.With will add "foo" only to the Returned context,
+	// which will limits its scope to the rest of this function (helloUser) and
+	// any functions called by helloUser and passed this context.
+	// The original caller of helloUser and all the middlewares will NOT see
+	// "foo", because it is only part of the newly returned ctx.
+	ctx = slogctx.With(ctx, "foo", "bar")
+
+	// Log some things.
+	// Should also have both "path", "id", and "foo"
+	slogctx.Info(ctx, "saying hello...")
+	/*
+		{
+			"time": "2024-04-01T00:06:11Z",
+			"level": "INFO",
+			"msg": "saying hello...",
+			"path": "/hello",
+			"id": "24680",
+			"foo": "bar"
+		}
+	*/
+
+	// Response
+	_, _ = w.Write([]byte("Hello User #" + id))
+}
+```
+
 ### slog-multi Middleware
 This library has a convenience method that allow it to interoperate with [github.com/samber/slog-multi](https://github.com/samber/slog-multi),
 in order to easily setup slog workflows such as pipelines, fanout, routing, failover, etc.

attrs.go

@@ -5,6 +5,8 @@ import (
 	"log/slog"
 	"slices"
 	"time"
+
+	"github.com/veqryn/slog-context/internal/attr"
 )
 
 // Prepend key for context.valueCtx
@@ -24,9 +26,9 @@ func Prepend(parent context.Context, args ...any) context.Context {
 
 	if v, ok := parent.Value(prependKey{}).([]slog.Attr); ok {
 		// Clip to ensure this is a scoped copy
-		return context.WithValue(parent, prependKey{}, append(slices.Clip(v), argsToAttrSlice(args)...))
+		return context.WithValue(parent, prependKey{}, append(slices.Clip(v), attr.ArgsToAttrSlice(args)...))
 	}
-	return context.WithValue(parent, prependKey{}, argsToAttrSlice(args))
+	return context.WithValue(parent, prependKey{}, attr.ArgsToAttrSlice(args))
 }
 
 // ExtractPrepended is an AttrExtractor that returns the prepended attributes
@@ -50,9 +52,9 @@ func Append(parent context.Context, args ...any) context.Context {
 
 	if v, ok := parent.Value(appendKey{}).([]slog.Attr); ok {
 		// Clip to ensure this is a scoped copy
-		return context.WithValue(parent, appendKey{}, append(slices.Clip(v), argsToAttrSlice(args)...))
+		return context.WithValue(parent, appendKey{}, append(slices.Clip(v), attr.ArgsToAttrSlice(args)...))
 	}
-	return context.WithValue(parent, appendKey{}, argsToAttrSlice(args))
+	return context.WithValue(parent, appendKey{}, attr.ArgsToAttrSlice(args))
 }
 
 // ExtractAppended is an AttrExtractor that returns the appended attributes
@@ -64,44 +66,3 @@ func ExtractAppended(ctx context.Context, _ time.Time, _ slog.Level, _ string) [
 	}
 	return nil
 }
-
-// Turn a slice of arguments, some of which pairs of primitives,
-// some might be attributes already, into a slice of attributes.
-// This is copied from golang sdk.
-func argsToAttrSlice(args []any) []slog.Attr {
-	var (
-		attr  slog.Attr
-		attrs []slog.Attr
-	)
-	for len(args) > 0 {
-		attr, args = argsToAttr(args)
-		attrs = append(attrs, attr)
-	}
-	return attrs
-}
-
-// This is copied from golang sdk.
-const badKey = "!BADKEY"
-
-// argsToAttr turns a prefix of the nonempty args slice into an Attr
-// and returns the unconsumed portion of the slice.
-// If args[0] is an Attr, it returns it.
-// If args[0] is a string, it treats the first two elements as
-// a key-value pair.
-// Otherwise, it treats args[0] as a value with a missing key.
-// This is copied from golang sdk.
-func argsToAttr(args []any) (slog.Attr, []any) {
-	switch x := args[0].(type) {
-	case string:
-		if len(args) == 1 {
-			return slog.String(badKey, x), nil
-		}
-		return slog.Any(x, args[1]), args[2:]
-
-	case slog.Attr:
-		return x, args[1:]
-
-	default:
-		return slog.Any(badKey, x), args[1:]
-	}
-}

ctx_test.go

@@ -6,27 +6,27 @@ import (
 	"errors"
 	"log/slog"
 	"testing"
+
+	"github.com/veqryn/slog-context/internal/test"
 )
 
 func TestCtx(t *testing.T) {
-	t.Parallel()
-
 	buf := &bytes.Buffer{}
 	h := slog.NewJSONHandler(buf, &slog.HandlerOptions{
 		AddSource: false,
 		Level:     slog.LevelDebug,
 		ReplaceAttr: func(groups []string, a slog.Attr) slog.Attr {
 			// fmt.Printf("ReplaceAttr: key:%s valueKind:%s value:%s nilGroups:%t groups:%#+v\n", a.Key, a.Value.Kind().String(), a.Value.String(), groups == nil, groups)
 			if groups == nil && a.Key == slog.TimeKey {
-				return slog.Time(slog.TimeKey, defaultTime)
+				return slog.Time(slog.TimeKey, test.DefaultTime)
 			}
 			return a
 		},
 	})
 
 	// Confirm FromCtx retrieves default if nothing stored in ctx yet
 	l := slog.New(h)
-	slog.SetDefault(l)
+	slog.SetDefault(l) // Can cause issues in tests run in parallel, so don't use it in other tests, just this test
 	if FromCtx(nil) != l {
 		t.Error("Expecting default logger retrieved")
 	}
@@ -58,6 +58,13 @@ func TestCtx(t *testing.T) {
 	}
 
 	// Test with wrappers
+	buf.Reset()
+	Log(ctx, slog.LevelDebug-10, "ignored")
+	LogAttrs(ctx, slog.LevelDebug-10, "ignored")
+	if buf.String() != "" {
+		t.Errorf("Expected:\n%s\nGot:\n%s\n", "", buf.String())
+	}
+
 	buf.Reset()
 	Debug(ctx, "main message", "main1", "arg1", "main1", "arg2")
 	expectedDebug := `{"time":"2023-09-29T13:00:59Z","level":"DEBUG","msg":"main message","with1":"arg1","with1":"arg2","with2":"arg1","with2":"arg2","group1":{"with4":"arg1","with4":"arg2","with5":"arg1","with5":"arg2","main1":"arg1","main1":"arg2"}}

examples/go.mod

@@ -4,7 +4,7 @@ go 1.21
 
 require (
 	github.com/veqryn/slog-context v0.6.0
-	github.com/veqryn/slog-context/otel v0.5.1
+	github.com/veqryn/slog-context/otel v0.6.0
 	go.opentelemetry.io/otel v1.24.0
 	go.opentelemetry.io/otel/exporters/stdout/stdouttrace v1.24.0
 	go.opentelemetry.io/otel/sdk v1.24.0

examples/go.sum

@@ -13,8 +13,8 @@ github.com/stretchr/testify v1.8.4 h1:CcVxjf3Q8PM0mHUKJCdn+eZZtm5yQwehR5yeSVQQcU
 github.com/stretchr/testify v1.8.4/go.mod h1:sz/lmYIOXD/1dqDmKjjqLyZ2RngseejIcXlSw2iwfAo=
 github.com/veqryn/slog-context v0.6.0 h1:RV0DL6SIXwTjKu5hUfZlreitiQ47HG6BA7G/aQINK9A=
 github.com/veqryn/slog-context v0.6.0/go.mod h1:E+qpdyiQs2YKRxFnX1JjpdFE1z3Ka94Kem2q9ZG6Jjo=
-github.com/veqryn/slog-context/otel v0.5.1 h1:X/UmUK+YJHTun7TVwSfOTAkfbhlpPCr7W6WjfHDF3qw=
-github.com/veqryn/slog-context/otel v0.5.1/go.mod h1:C+F2oB2BnozIuBHw7cvenou3fpDJqfOvMvKNA7RS5jA=
+github.com/veqryn/slog-context/otel v0.6.0 h1:LwVMzfKMFhVpIKPASwa4IkzgL8+/bmyrFWJYrBIkpf0=
+github.com/veqryn/slog-context/otel v0.6.0/go.mod h1:0l6vQ7IqZHKq1MH7pyhNlbdUutBcuiGYJluAPLQ33Nk=
 go.opentelemetry.io/otel v1.24.0 h1:0LAOdjNmQeSTzGBzduGe/rU4tZhMwL5rWgtp9Ku5Jfo=
 go.opentelemetry.io/otel v1.24.0/go.mod h1:W7b9Ozg4nkF5tWI5zsXkaKKDjdVjpD4oAt9Qi/MArHo=
 go.opentelemetry.io/otel/exporters/stdout/stdouttrace v1.24.0 h1:s0PHtIkN+3xrbDOpt2M8OTG92cWqUESvzh2MxiR5xY8=

handler_test.go

@@ -8,6 +8,8 @@ import (
 	"strings"
 	"testing"
 	"time"
+
+	"github.com/veqryn/slog-context/internal/test"
 )
 
 type logLine struct {
@@ -21,7 +23,7 @@ type logLine struct {
 func TestHandler(t *testing.T) {
 	t.Parallel()
 
-	tester := &testHandler{}
+	tester := &test.Handler{}
 	h := NewHandler(tester, nil)
 
 	ctx := Prepend(nil, "prepend1", "arg1", slog.String("prepend1", "arg2"))
@@ -35,8 +37,8 @@ func TestHandler(t *testing.T) {
 
 	l := slog.New(h)
 
-	l = l.With("with1", "arg1", "with1", "arg2")
-	l = l.WithGroup("group1")
+	l = l.With("with1", "arg1", "with1", "arg2").With()
+	l = l.WithGroup("group1").WithGroup("")
 	l = l.With("with2", "arg1", "with2", "arg2")
 
 	l.InfoContext(ctx, "main message", "main1", "arg1", "main1", "arg2")
@@ -59,7 +61,7 @@ func TestHandler(t *testing.T) {
 	}
 
 	// Check the source location fields
-	tester.source = true
+	tester.Source = true
 	b, err = tester.MarshalJSON()
 	if err != nil {
 		t.Fatal(err)
@@ -73,15 +75,15 @@ func TestHandler(t *testing.T) {
 
 	if unmarshalled.Source.Function != "github.com/veqryn/slog-context.TestHandler" ||
 		!strings.HasSuffix(unmarshalled.Source.File, "slog-context/handler_test.go") ||
-		unmarshalled.Source.Line != 42 {
+		unmarshalled.Source.Line != 44 {
 		t.Errorf("Expected source fields are incorrect: %#+v\n", unmarshalled)
 	}
 }
 
 func TestHandlerMultipleAttrExtractor(t *testing.T) {
 	t.Parallel()
 
-	tester := &testHandler{}
+	tester := &test.Handler{}
 	h := NewMiddleware(&HandlerOptions{
 		Prependers: []AttrExtractor{
 			ExtractPrepended,
@@ -95,6 +97,9 @@ func TestHandlerMultipleAttrExtractor(t *testing.T) {
 				}
 				return nil
 			},
+			func(_ context.Context, _ time.Time, _ slog.Level, _ string) []slog.Attr {
+				return []slog.Attr{}
+			},
 		},
 		Appenders: []AttrExtractor{
 			ExtractAppended,
@@ -108,6 +113,9 @@ func TestHandlerMultipleAttrExtractor(t *testing.T) {
 				}
 				return nil
 			},
+			func(_ context.Context, _ time.Time, _ slog.Level, _ string) []slog.Attr {
+				return nil
+			},
 		},
 	})(tester)