diff --git a/debug/README.md b/debug/README.md index 683b3e1d..640cd990 100644 --- a/debug/README.md +++ b/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 diff --git a/debug/debug.go b/debug/debug.go index 7c6583b1..f4085ed0 100644 --- a/debug/debug.go +++ b/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 diff --git a/debug/grpc.go b/debug/grpc.go index 13ae8761..54ae8ad0 100644 --- a/debug/grpc.go +++ b/debug/grpc.go @@ -10,7 +10,8 @@ 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, @@ -18,7 +19,7 @@ func UnaryServerInterceptor() grpc.UnaryServerInterceptor { _ *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()) diff --git a/debug/grpc_test.go b/debug/grpc_test.go index 53ac84a1..336373ee 100644 --- a/debug/grpc_test.go +++ b/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() { diff --git a/debug/http.go b/debug/http.go index 9a2f5891..60722bdc 100644 --- a/debug/http.go +++ b/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 } diff --git a/debug/options.go b/debug/options.go index f30d2e5d..5e759fa9 100644 --- a/debug/options.go +++ b/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) { diff --git a/debug/state_test.go b/debug/state_test.go new file mode 100644 index 00000000..510f2e0d --- /dev/null +++ b/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) + } +} diff --git a/log/context_test.go b/log/context_test.go index 64036357..0bb67846 100644 --- a/log/context_test.go +++ b/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 ... ", changed.String()) + assert.True(t, DebugEnabled(base)) + assert.False(t, DebugEnabled(copy)) +} diff --git a/log/grpc.go b/log/grpc.go index b729fa51..036e4b3f 100644 --- a/log/grpc.go +++ b/log/grpc.go @@ -35,7 +35,7 @@ type ( var shortID = randShortID // UnaryServerInterceptor returns a unary interceptor that performs two tasks: -// 1. Enriches the request context with the logger specified in logCtx. +// 1. Creates a request-local copy of the logger specified in logCtx. // 2. Logs details of the unary call, unless the WithDisableCallLogging option is provided. // UnaryServerInterceptor panics if logCtx was not created with Context. func UnaryServerInterceptor(logCtx context.Context, opts ...GRPCLogOption) grpc.UnaryServerInterceptor { @@ -59,6 +59,8 @@ func UnaryServerInterceptor(logCtx context.Context, opts ...GRPCLogOption) grpc. ctx = WithContext(ctx, logCtx) if !o.disableCallID { ctx = With(ctx, KV{RequestIDKey, shortID()}) + } else { + ctx = With(ctx) } if o.disableCallLogging { return handler(ctx, req) @@ -85,7 +87,7 @@ func UnaryServerInterceptor(logCtx context.Context, opts ...GRPCLogOption) grpc. } // StreamServerInterceptor returns a stream interceptor that performs two tasks: -// 1. Enriches the request context with the logger specified in logCtx. +// 1. Creates a stream-local copy of the logger specified in logCtx. // 2. Logs details of the stream call, unless the WithDisableCallLogging option is provided. // StreamServerInterceptor panics if logCtx was not created with Context. func StreamServerInterceptor(logCtx context.Context, opts ...GRPCLogOption) grpc.StreamServerInterceptor { @@ -109,6 +111,8 @@ func StreamServerInterceptor(logCtx context.Context, opts ...GRPCLogOption) grpc ctx := WithContext(stream.Context(), logCtx) if !o.disableCallID { ctx = With(ctx, KV{RequestIDKey, shortID()}) + } else { + ctx = With(ctx) } stream = &streamWithContext{stream, ctx} if o.disableCallLogging { diff --git a/log/grpc_test.go b/log/grpc_test.go index 54fe50fa..b9967a5e 100644 --- a/log/grpc_test.go +++ b/log/grpc_test.go @@ -56,6 +56,12 @@ func TestUnaryServerInterceptor(t *testing.T) { method: logUnaryMethod, expected: logged + "\n", }, + { + name: "with disable call ID", + options: []GRPCLogOption{WithDisableCallID()}, + method: logUnaryMethod, + expected: strings.ReplaceAll(prefix+"\n"+logged+"\n"+suffix+"\n", `"request_id":"test-request-id",`, ""), + }, } for _, c := range cases { t.Run(c.name, func(t *testing.T) { @@ -119,6 +125,12 @@ func TestStreamServerTrace(t *testing.T) { method: echoMethod, expected: logged + "\n", }, + { + name: "with disable call ID", + options: []GRPCLogOption{WithDisableCallID()}, + method: echoMethod, + expected: strings.ReplaceAll(prefix+"\n"+logged+"\n"+suffix+"\n", `"request_id":"test-request-id",`, ""), + }, } for _, c := range cases { t.Run(c.name, func(t *testing.T) { diff --git a/log/http.go b/log/http.go index f126fa93..ddb0cbbc 100644 --- a/log/http.go +++ b/log/http.go @@ -51,7 +51,7 @@ type ( ) // HTTP returns a HTTP middleware that performs two tasks: -// 1. Enriches the request context with the logger specified in logCtx. +// 1. Creates a request-local copy of the logger specified in logCtx. // 2. Logs HTTP request details, except when WithDisableRequestLogging is set or // URL path matches a WithPathFilter regex. // @@ -81,6 +81,8 @@ func HTTP(logCtx context.Context, opts ...HTTPLogOption) func(http.Handler) http ctx := WithContext(req.Context(), logCtx) if !options.disableRequestID { ctx = With(ctx, KV{RequestIDKey, shortID()}) + } else { + ctx = With(ctx) } if options.disableRequestLogging { h.ServeHTTP(w, req.WithContext(ctx)) diff --git a/log/http_test.go b/log/http_test.go index 6170507b..b2d97369 100644 --- a/log/http_test.go +++ b/log/http_test.go @@ -46,6 +46,11 @@ func TestHTTP(t *testing.T) { opt: WithDisableRequestLogging(), expected: entry + "\n", }, + { + name: "with disable request ID", + opt: WithDisableRequestID(), + expected: strings.ReplaceAll(prefix+"\n"+entry+"\n"+suffix+"\n", `"request_id":"test-request-id",`, ""), + }, } for _, c := range cases { t.Run(c.name, func(t *testing.T) { diff --git a/log/log.go b/log/log.go index f57117cc..a735933e 100644 --- a/log/log.go +++ b/log/log.go @@ -7,6 +7,7 @@ import ( "fmt" "io" "os" + "slices" "sync" "time" ) @@ -137,7 +138,8 @@ func Fatalf(ctx context.Context, err error, format string, v ...any) { // With creates a copy of the given log context and appends the given key/value // pairs to it. Values must be strings, numbers, booleans, nil or a slice of -// these types. +// these types. Changing the copy's logging options does not change the original +// context. The configured output writers themselves are still shared. func With(ctx context.Context, keyvals ...Fielder) context.Context { v := ctx.Value(ctxLogger) if v == nil { @@ -146,8 +148,12 @@ func With(ctx context.Context, keyvals ...Fielder) context.Context { l := v.(*logger) l.lock.Lock() defer l.lock.Unlock() + options := *l.options + options.outputs = slices.Clone(options.outputs) + options.keyvals = slices.Clone(options.keyvals) + options.kvfuncs = slices.Clone(options.kvfuncs) newLogger := logger{ - options: l.options, + options: &options, entries: l.entries, keyvals: l.keyvals.merge(keyvals), flushed: l.flushed,