Initialize debug logging at startup and isolate request settings

debug/README.md

@@ -21,6 +21,24 @@ and does not change the state if the request does not contain a `debug-logs`
 query parameter.  The path, query parameter name and value can be customized by
 passing options to the `MountDebugLogEnabler` function.
 
+Debug logging starts off. To enable it at startup, pass
+`debug.WithInitialState(true)` when mounting the handler, before starting the
+servers. The setting is shared by all debug handlers in the process. Mounting
+another handler without this option preserves the state; when several handlers
+specify an initial state, the last mounted value wins. The HTTP control can
+still turn logging on or off afterward. Each HTTP request, unary RPC and stream
+keeps the setting it had when it started; a toggle affects subsequent requests,
+not already-running streams.
+When supplying a configured logger, place Clue's `log.HTTP`,
+`log.UnaryServerInterceptor`, or `log.StreamServerInterceptor` before the
+corresponding debug middleware. These create the request-local logger and keep
+its buffered messages available if the request later fails. Debug middleware
+also works without a supplied logger; it then creates a default logger.
+
+```go
+debug.MountDebugLogEnabler(mux, debug.WithInitialState(debugEnabled))
+```
+
 Note that for the debug log state to take effect, HTTP servers must use handlers
 returned by the HTTP function and gRPC servers must make use of the
 UnaryInterceptor or StreamInterceptor interceptors.  Also note that gRPC

debug/debug.go

@@ -6,6 +6,7 @@ import (
 	"net/http"
 	"net/http/pprof"
 	"strings"
+	"sync/atomic"
 
 	goa "goa.design/goa/v3/pkg"
 
@@ -21,7 +22,7 @@ type Muxer interface {
 
 var (
 	// debugLogs is true if debug logs should be enabled.
-	debugLogs bool
+	debugLogs atomic.Bool
 )
 
 // MountDebugLogEnabler mounts an endpoint under "/debug" that manages the
@@ -31,6 +32,8 @@ var (
 // cases the endpoint returns the current debug logs status. The path, query
 // parameter name and values can be changed using the WithPath, WithQuery,
 // WithOnValue and WithOffValue options.
+// WithInitialState sets the process-wide starting state. Mount handlers before
+// serving requests; mounting without this option leaves the current state alone.
 //
 // Note: the endpoint merely controls the status of debug logs. It does not
 // actually configure the current logger. The logger is configured by the
@@ -42,16 +45,19 @@ func MountDebugLogEnabler(mux Muxer, opts ...DebugLogEnablerOption) {
 	for _, opt := range opts {
 		opt(o)
 	}
+	if o.initialState != nil {
+		debugLogs.Store(*o.initialState)
+	}
 	if !strings.HasPrefix(o.path, "/") {
 		o.path = "/" + o.path
 	}
 	mux.Handle(o.path, http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
 		if q := r.URL.Query().Get(o.query); q == o.onval {
-			debugLogs = true
+			debugLogs.Store(true)
 		} else if q == o.offval {
-			debugLogs = false
+			debugLogs.Store(false)
 		}
-		if debugLogs {
+		if debugLogs.Load() {
 			fmt.Fprintf(w, `{"%s":"%s"}`, o.query, o.onval) // nolint: errcheck
 		} else {
 			fmt.Fprintf(w, `{"%s":"%s"}`, o.query, o.offval) // nolint: errcheck

debug/grpc.go

@@ -10,15 +10,16 @@ import (
 
 // UnaryServerInterceptor return an interceptor that manages whether debug log
 // entries are written. This interceptor should be used in conjunction with the
-// MountDebugLogEnabler function.
+// MountDebugLogEnabler function. An existing logger must be request-local;
+// placing log.UnaryServerInterceptor before this interceptor creates one.
 func UnaryServerInterceptor() grpc.UnaryServerInterceptor {
 	return func(
 		ctx context.Context,
 		req any,
 		_ *grpc.UnaryServerInfo,
 		handler grpc.UnaryHandler,
 	) (any, error) {
-		if debugLogs {
+		if debugLogs.Load() {
 			ctx = log.Context(ctx, log.WithDebug())
 		} else {
 			ctx = log.Context(ctx, log.WithNoDebug())
@@ -30,7 +31,9 @@ func UnaryServerInterceptor() grpc.UnaryServerInterceptor {
 // StreamServerInterceptor returns a stream interceptor that manages whether
 // debug log entries are written. Note: a change in the debug setting is
 // effective only for the next stream request. This interceptor should be used
-// in conjunction with the MountDebugLogEnabler function.
+// in conjunction with the MountDebugLogEnabler function. An existing logger
+// must belong to this stream; placing log.StreamServerInterceptor before this
+// interceptor creates one.
 func StreamServerInterceptor() grpc.StreamServerInterceptor {
 	return func(
 		srv any,
@@ -39,7 +42,7 @@ func StreamServerInterceptor() grpc.StreamServerInterceptor {
 		handler grpc.StreamHandler,
 	) error {
 		ctx := stream.Context()
-		if debugLogs {
+		if debugLogs.Load() {
 			ctx = log.Context(ctx, log.WithDebug())
 		} else {
 			ctx = log.Context(ctx, log.WithNoDebug())

debug/grpc_test.go

@@ -73,7 +73,7 @@ func TestStreamServerInterceptor(t *testing.T) {
 		{"revert to no debug logs", false, ""},
 	}
 	for _, step := range steps {
-		debugLogs = step.enableDebugLogs
+		debugLogs.Store(step.enableDebugLogs)
 		stream, err := cli.GRPCStream(context.Background())
 		assert.NoError(t, err)
 		defer func() {

debug/http.go

@@ -8,18 +8,18 @@ import (
 
 // HTTP returns a middleware that manages whether debug log entries are written.
 // This middleware should be used in conjunction with the MountDebugLogEnabler
-// function.
+// function. If the request already has a logger, it must be request-local;
+// placing log.HTTP before this middleware creates one.
 func HTTP() func(http.Handler) http.Handler {
 	return func(next http.Handler) http.Handler {
 		handler := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
-			if debugLogs {
-				ctx := log.Context(r.Context(), log.WithDebug())
-				r = r.WithContext(ctx)
+			ctx := r.Context()
+			if debugLogs.Load() {
+				ctx = log.Context(ctx, log.WithDebug())
 			} else {
-				ctx := log.Context(r.Context(), log.WithNoDebug())
-				r = r.WithContext(ctx)
+				ctx = log.Context(ctx, log.WithNoDebug())
 			}
-			next.ServeHTTP(w, r)
+			next.ServeHTTP(w, r.WithContext(ctx))
 		})
 		return handler
 	}

debug/options.go

@@ -30,10 +30,11 @@ type (
 	}
 
 	dleOptions struct {
-		path   string
-		query  string
-		onval  string
-		offval string
+		initialState *bool
+		path         string
+		query        string
+		onval        string
+		offval       string
 	}
 
 	pprofOptions struct {
@@ -68,6 +69,16 @@ func WithClient() LogPayloadsOption {
 	}
 }
 
+// WithInitialState sets the process-wide debug setting when the handler is
+// mounted, before serving requests. Without this option the setting is unchanged
+// (initially off). If several handlers specify it, the last mounted value wins.
+// HTTP requests to any mounted handler can still change the setting afterward.
+func WithInitialState(enabled bool) DebugLogEnablerOption {
+	return func(o *dleOptions) {
+		o.initialState = &enabled
+	}
+}
+
 // WithPath sets the URL path used by MountDebugLogEnabler.
 func WithPath(path string) DebugLogEnablerOption {
 	return func(o *dleOptions) {

debug/state_test.go

@@ -0,0 +1,168 @@
+package debug
+
+import (
+	"bytes"
+	"context"
+	"errors"
+	"io"
+	"net/http"
+	"net/http/httptest"
+	"sync"
+	"testing"
+
+	"github.com/stretchr/testify/assert"
+	"google.golang.org/grpc"
+
+	"goa.design/clue/log"
+)
+
+func TestDebugFailureKeepsBufferedLogs(t *testing.T) {
+	debugLogs.Store(false)
+	for _, transport := range []string{"unary", "stream"} {
+		t.Run(transport, func(t *testing.T) {
+			var output bytes.Buffer
+			base := log.Context(context.Background(), log.WithOutputs(log.Output{Writer: &output, Format: logKeyValsOnly}))
+			failure := errors.New("request failed")
+			switch transport {
+			case "unary":
+				info := &grpc.UnaryServerInfo{FullMethod: "/test/call"}
+				_, err := log.UnaryServerInterceptor(base)(context.Background(), nil, info, func(ctx context.Context, req any) (any, error) {
+					return UnaryServerInterceptor()(ctx, req, info, func(ctx context.Context, _ any) (any, error) {
+						log.Info(ctx, log.KV{K: "step", V: "before failure"})
+						return nil, failure
+					})
+				})
+				assert.ErrorIs(t, err, failure)
+			case "stream":
+				info := &grpc.StreamServerInfo{FullMethod: "/test/call"}
+				err := log.StreamServerInterceptor(base)(nil, &streamWithContext{ctx: context.Background()}, info, func(srv any, stream grpc.ServerStream) error {
+					return StreamServerInterceptor()(srv, stream, info, func(_ any, stream grpc.ServerStream) error {
+						log.Info(stream.Context(), log.KV{K: "step", V: "before failure"})
+						return failure
+					})
+				})
+				assert.ErrorIs(t, err, failure)
+			}
+			assert.Contains(t, output.String(), "step=before failure")
+			assert.Contains(t, output.String(), "err=request failed")
+		})
+	}
+}
+
+func TestDebugInitialState(t *testing.T) {
+	t.Cleanup(func() {
+		debugLogs.Store(false)
+	})
+	for _, enabled := range []bool{true, false} {
+		mux := http.NewServeMux()
+		MountDebugLogEnabler(mux, WithInitialState(enabled))
+		for _, transport := range []string{"http", "unary", "stream"} {
+			serveDebugRequest(t, transport, log.Context(context.Background()), func(ctx context.Context) {
+				assert.Equal(t, enabled, log.DebugEnabled(ctx), transport)
+			})
+		}
+		// Without a configured logger, debug middleware creates one itself.
+		_, err := UnaryServerInterceptor()(context.Background(), nil, nil, func(ctx context.Context, _ any) (any, error) {
+			assert.Equal(t, enabled, log.DebugEnabled(ctx))
+			return nil, nil
+		})
+		assert.NoError(t, err)
+		err = StreamServerInterceptor()(nil, &streamWithContext{ctx: context.Background()}, nil, func(_ any, stream grpc.ServerStream) error {
+			assert.Equal(t, enabled, log.DebugEnabled(stream.Context()))
+			return nil
+		})
+		assert.NoError(t, err)
+		HTTP()(http.HandlerFunc(func(_ http.ResponseWriter, r *http.Request) {
+			assert.Equal(t, enabled, log.DebugEnabled(r.Context()))
+		})).ServeHTTP(httptest.NewRecorder(), httptest.NewRequest(http.MethodGet, "/", nil))
+		// Another listener without a startup choice uses the same process setting.
+		other := http.NewServeMux()
+		MountDebugLogEnabler(other)
+		response := httptest.NewRecorder()
+		other.ServeHTTP(response, httptest.NewRequest(http.MethodGet, "/debug", nil))
+		want := `{"debug-logs":"off"}`
+		if enabled {
+			want = `{"debug-logs":"on"}`
+		}
+		assert.Equal(t, want, response.Body.String())
+	}
+}
+
+func TestDebugRequestIsolation(t *testing.T) {
+	for _, transport := range []string{"http", "unary", "stream"} {
+		t.Run(transport, func(t *testing.T) {
+			mux := http.NewServeMux()
+			MountDebugLogEnabler(mux)
+			base := log.Context(context.Background())
+			mux.ServeHTTP(httptest.NewRecorder(), httptest.NewRequest(http.MethodGet, "/debug?debug-logs=on", nil))
+			var active context.Context
+			serveDebugRequest(t, transport, base, func(ctx context.Context) {
+				active = ctx
+				assert.True(t, log.DebugEnabled(ctx))
+			})
+			mux.ServeHTTP(httptest.NewRecorder(), httptest.NewRequest(http.MethodGet, "/debug?debug-logs=off", nil))
+			serveDebugRequest(t, transport, base, func(ctx context.Context) {
+				assert.False(t, log.DebugEnabled(ctx))
+			})
+			assert.True(t, log.DebugEnabled(active), "later requests must not change an earlier request's setting")
+			assert.False(t, log.DebugEnabled(base), "request settings must not change the startup logger")
+		})
+	}
+}
+
+func TestConcurrentDebugRequests(t *testing.T) {
+	mux := http.NewServeMux()
+	MountDebugLogEnabler(mux)
+	base := log.Context(context.Background(), log.WithOutputs(log.Output{Writer: io.Discard, Format: log.FormatJSON}))
+	var workers sync.WaitGroup
+	for _, transport := range []string{"http", "unary", "stream"} {
+		workers.Go(func() {
+			for range 100 {
+				serveDebugRequest(t, transport, log.With(base), func(ctx context.Context) {
+					log.DebugEnabled(ctx)
+					log.Debug(ctx, log.KV{K: "message", V: "concurrent request"})
+				})
+			}
+		})
+	}
+	workers.Go(func() {
+		for range 100 {
+			for _, state := range []string{"on", "off"} {
+				mux.ServeHTTP(httptest.NewRecorder(), httptest.NewRequest(http.MethodGet, "/debug?debug-logs="+state, nil))
+			}
+		}
+	})
+	workers.Wait()
+	debugLogs.Store(false)
+}
+
+// serveDebugRequest applies the real middleware to a request that already has
+// a logger, matching the order used by HTTP and gRPC services.
+func serveDebugRequest(t *testing.T, transport string, ctx context.Context, handler func(context.Context)) {
+	t.Helper()
+	switch transport {
+	case "http":
+		handler := HTTP()(http.HandlerFunc(func(_ http.ResponseWriter, r *http.Request) {
+			handler(r.Context())
+		}))
+		log.HTTP(ctx, log.WithDisableRequestID(), log.WithDisableRequestLogging())(handler).ServeHTTP(httptest.NewRecorder(), httptest.NewRequest(http.MethodGet, "/", nil))
+	case "unary":
+		info := &grpc.UnaryServerInfo{FullMethod: "/test/call"}
+		_, err := log.UnaryServerInterceptor(ctx, log.WithDisableCallID(), log.WithDisableCallLogging())(context.Background(), nil, info, func(ctx context.Context, req any) (any, error) {
+			return UnaryServerInterceptor()(ctx, req, info, func(ctx context.Context, _ any) (any, error) {
+				handler(ctx)
+				return nil, nil
+			})
+		})
+		assert.NoError(t, err)
+	case "stream":
+		info := &grpc.StreamServerInfo{FullMethod: "/test/call"}
+		err := log.StreamServerInterceptor(ctx, log.WithDisableCallID(), log.WithDisableCallLogging())(nil, &streamWithContext{ctx: context.Background()}, info, func(srv any, stream grpc.ServerStream) error {
+			return StreamServerInterceptor()(srv, stream, info, func(_ any, stream grpc.ServerStream) error {
+				handler(stream.Context())
+				return nil
+			})
+		})
+		assert.NoError(t, err)
+	}
+}

log/context_test.go

@@ -1,6 +1,7 @@
 package log
 
 import (
+	"bytes"
 	"context"
 	"testing"
 
@@ -13,3 +14,16 @@ func TestDebugEnabled(t *testing.T) {
 	ctx = Context(ctx, WithDebug())
 	assert.True(t, DebugEnabled(ctx), "expected debug logs to be enabled")
 }
+
+func TestWithIsolatesOptions(t *testing.T) {
+	var original, changed bytes.Buffer
+	base := Context(context.Background(), WithDebug(), WithOutputs(Output{Writer: &original, Format: testFormat}))
+	copy := Context(With(base), WithNoDebug(), WithOutput(&changed), WithMaxSize(4))
+	Debugf(base, "original")
+	Debugf(copy, "hidden")
+	Printf(copy, "changed")
+	assert.Equal(t, "original", original.String())
+	assert.Equal(t, "chan ... <clue/log.truncated>", changed.String())
+	assert.True(t, DebugEnabled(base))
+	assert.False(t, DebugEnabled(copy))
+}