diff --git a/go.mod b/go.mod index 14f0d89..2ba34de 100644 --- a/go.mod +++ b/go.mod @@ -5,16 +5,17 @@ go 1.25.9 require ( buf.build/go/protovalidate v1.1.3 github.com/afex/hystrix-go v0.0.0-20180502004556-fa1af6a1f4f5 - github.com/go-coldbrew/errors v0.2.13 - github.com/go-coldbrew/log v0.3.1 + github.com/go-coldbrew/errors v0.2.14 + github.com/go-coldbrew/log v0.3.2 github.com/go-coldbrew/options v0.3.0 - github.com/go-coldbrew/tracing v0.2.0 + github.com/go-coldbrew/tracing v0.2.2 github.com/grpc-ecosystem/go-grpc-middleware/providers/prometheus v1.1.0 github.com/grpc-ecosystem/go-grpc-middleware/v2 v2.3.3 github.com/grpc-ecosystem/grpc-gateway/v2 v2.28.0 github.com/newrelic/go-agent/v3 v3.42.0 github.com/newrelic/go-agent/v3/integrations/nrgrpc v1.4.7 github.com/prometheus/client_golang v1.23.2 + go.uber.org/goleak v1.3.0 google.golang.org/grpc v1.79.3 ) diff --git a/go.sum b/go.sum index 0fec9ba..8a1ecf3 100644 --- a/go.sum +++ b/go.sum @@ -179,14 +179,14 @@ github.com/ghostiam/protogetter v0.3.20 h1:oW7OPFit2FxZOpmMRPP9FffU4uUpfeE/rEdE1 github.com/ghostiam/protogetter v0.3.20/go.mod h1:FjIu5Yfs6FT391m+Fjp3fbAYJ6rkL/J6ySpZBfnODuI= github.com/gliderlabs/ssh v0.3.8 h1:a4YXD1V7xMF9g5nTkdfnja3Sxy1PVDCj1Zg4Wb8vY6c= github.com/gliderlabs/ssh v0.3.8/go.mod h1:xYoytBv1sV0aL3CavoDuJIQNURXkkfPA/wxQ1pL1fAU= -github.com/go-coldbrew/errors v0.2.13 h1:OUOEWLml6Mstt0Sskc94VVPhZ/rMfONeNOlHqycaq1g= -github.com/go-coldbrew/errors v0.2.13/go.mod h1:eFLqeTPhgGyvsVVRXcdKGUxEnm+chrpddhL8lfogonk= -github.com/go-coldbrew/log v0.3.1 h1:Cyx6KWBW3wZE8dSru6mIDFtUnJ1R2h6C44ZDo5bOqAo= -github.com/go-coldbrew/log v0.3.1/go.mod h1:xxZGHBfni5eXc6Azg+g8UPTmqTJLAf9sX46gAT8o39Y= +github.com/go-coldbrew/errors v0.2.14 h1:SQcV9Kw+hNfNGXjvu4fWl5uXw5NRD6lW+rkHgtzAYZE= +github.com/go-coldbrew/errors v0.2.14/go.mod h1:f9eGGKKF9KmyCpSWZRSqqV4HRWqbzmh1E9lyL8jyL+Y= +github.com/go-coldbrew/log v0.3.2 h1:CoHa0PGX7a7o/Cv/ke7PdQfq4LKtbPVypUf3uXcRLMs= +github.com/go-coldbrew/log v0.3.2/go.mod h1:tumRNCmLWRep5wnhS/vzDQ7UMinF6OZ7WW8K/qlXAzc= github.com/go-coldbrew/options v0.3.0 h1:JwyVntb9bzBeFdaHFK6yGVVz30G3aVlqJJ6uVyYQfCc= github.com/go-coldbrew/options v0.3.0/go.mod h1:8JlmgVJXFoY1KiDLsyMmR//q1U1aBItCexvTrVT2Y60= -github.com/go-coldbrew/tracing v0.2.0 h1:WGfdp5PNunOGfjTZGXPFaip3G5qOOMP622JFYA90ML4= -github.com/go-coldbrew/tracing v0.2.0/go.mod h1:phF8WDsadDKK20lgB0Zv2/ocVIrCbVziMd3MMxqr+aU= +github.com/go-coldbrew/tracing v0.2.2 h1:pvRMSwla5txZgtQOi18OqsuJhtsqPbfeC1arH9tJMys= +github.com/go-coldbrew/tracing v0.2.2/go.mod h1:mMYoCOqxFN28fEPMFbufwK0w/6rCiSjGftSr0KrZ0T0= github.com/go-critic/go-critic v0.14.3 h1:5R1qH2iFeo4I/RJU8vTezdqs08Egi4u5p6vOESA0pog= github.com/go-critic/go-critic v0.14.3/go.mod h1:xwntfW6SYAd7h1OqDzmN6hBX/JxsEKl5up/Y2bsxgVQ= github.com/go-errors/errors v1.4.2 h1:J6MZopCL4uSllY1OfXM374weqZFFItUbrImctkmUxIA= diff --git a/goleak_test.go b/goleak_test.go new file mode 100644 index 0000000..2ced296 --- /dev/null +++ b/goleak_test.go @@ -0,0 +1,21 @@ +package interceptors + +import ( + "testing" + + "go.uber.org/goleak" +) + +func TestMain(m *testing.M) { + goleak.VerifyTestMain(m, + // rollbar-go creates a global async client at package init time + // (rollbar.go:39: std = NewAsync(...)), starting a background goroutine + // unconditionally when the package is imported. Cannot be avoided. + goleak.IgnoreTopFunction("github.com/rollbar/rollbar-go.NewAsyncTransport.func1"), + // hystrix-go starts metric exchange and pool metric goroutines when a + // circuit breaker is first used in tests. These are global singletons + // with no cleanup API. + goleak.IgnoreTopFunction("github.com/afex/hystrix-go/hystrix.(*metricExchange).Monitor"), + goleak.IgnoreTopFunction("github.com/afex/hystrix-go/hystrix.(*poolMetrics).Monitor"), + ) +} diff --git a/interceptors.go b/interceptors.go index a6b3da1..e70609e 100644 --- a/interceptors.go +++ b/interceptors.go @@ -33,6 +33,7 @@ import ( newrelic "github.com/newrelic/go-agent/v3/newrelic" "github.com/prometheus/client_golang/prometheus" "google.golang.org/grpc" + "google.golang.org/grpc/metadata" "google.golang.org/grpc/status" ) @@ -69,6 +70,8 @@ var ( srvMetrics *grpcprom.ServerMetrics cltMetricsOnce sync.Once cltMetrics *grpcprom.ClientMetrics + disableDebugLogInterceptor bool + debugLogHeaderName = "x-debug-log-level" ) // SetResponseTimeLogLevel sets the log level for response time logging. @@ -430,6 +433,9 @@ func DefaultInterceptors() []grpc.UnaryServerInterceptor { ResponseTimeLoggingInterceptor(defaultFilterFunc), TraceIdInterceptor(), ) + if !disableDebugLogInterceptor { + ints = append(ints, DebugLogInterceptor()) + } if !disableProtoValidate { ints = append(ints, ProtoValidateInterceptor()) } @@ -798,3 +804,59 @@ func TraceIdInterceptor() grpc.UnaryServerInterceptor { return handler(ctx, req) } } + +// SetDisableDebugLogInterceptor disables the DebugLogInterceptor in the default +// interceptor chain. Must be called during initialization, before the server starts. +func SetDisableDebugLogInterceptor(disable bool) { + disableDebugLogInterceptor = disable +} + +// SetDebugLogHeaderName sets the gRPC metadata header name that triggers +// per-request log level override. Default is "x-debug-log-level". The header +// value should be a valid log level (e.g., "debug"). Empty names are ignored. +// Must be called during initialization. +func SetDebugLogHeaderName(name string) { + name = strings.ToLower(strings.TrimSpace(name)) + if name == "" { + return + } + debugLogHeaderName = name +} + +// GetDebugLogHeaderName returns the current debug log header name. +func GetDebugLogHeaderName() string { + return debugLogHeaderName +} + +// DebugLogInterceptor enables per-request log level override based on a proto +// field or gRPC metadata header. It checks (in order): +// 1. Proto field: GetDebug() bool or GetEnableDebug() bool — always sets DebugLevel +// 2. Metadata header: configurable via SetDebugLogHeaderName (default "x-debug-log-level") +// — the header value is parsed as a log level, allowing any valid level (debug, info, warn, error) +// +// Combined with ColdBrew's trace ID propagation, this allows enabling debug +// logging for a single request and following it across services via trace ID. +func DebugLogInterceptor() grpc.UnaryServerInterceptor { + return func(ctx context.Context, req any, info *grpc.UnaryServerInfo, handler grpc.UnaryHandler) (resp any, err error) { + // Check proto field first + if req != nil { + if r, ok := req.(interface{ GetDebug() bool }); ok && r.GetDebug() { + ctx = log.OverrideLogLevel(ctx, loggers.DebugLevel) + return handler(ctx, req) + } + if r, ok := req.(interface{ GetEnableDebug() bool }); ok && r.GetEnableDebug() { + ctx = log.OverrideLogLevel(ctx, loggers.DebugLevel) + return handler(ctx, req) + } + } + // Check gRPC metadata header + if md, ok := metadata.FromIncomingContext(ctx); ok { + if vals := md.Get(debugLogHeaderName); len(vals) > 0 { + if level, err := loggers.ParseLevel(vals[0]); err == nil { + ctx = log.OverrideLogLevel(ctx, level) + } + } + } + return handler(ctx, req) + } +} diff --git a/interceptors_test.go b/interceptors_test.go index 2f74afc..9ed6d3b 100644 --- a/interceptors_test.go +++ b/interceptors_test.go @@ -10,6 +10,7 @@ import ( "testing" "time" + "github.com/go-coldbrew/log" "github.com/go-coldbrew/log/loggers" "github.com/grpc-ecosystem/grpc-gateway/v2/runtime" "google.golang.org/grpc" @@ -46,6 +47,8 @@ func resetGlobals() { defaultTimeout = 60 * time.Second httpToGRPCOnce = sync.Once{} httpToGRPCInterceptor = nil + disableDebugLogInterceptor = false + debugLogHeaderName = "x-debug-log-level" } func TestFilterMethodsFunc(t *testing.T) { @@ -1137,3 +1140,169 @@ func TestDefaultInterceptors_IncludesTimeout(t *testing.T) { t.Error("expected first CB interceptor (DefaultTimeoutInterceptor) to set a deadline") } } + +// --- DebugLogInterceptor tests --- + +type debugRequest struct{ debug bool } + +func (r *debugRequest) GetDebug() bool { return r.debug } + +type enableDebugRequest struct{ enable bool } + +func (r *enableDebugRequest) GetEnableDebug() bool { return r.enable } + +type plainRequest struct{} + +func TestDebugLogInterceptor_ProtoFieldDebug(t *testing.T) { + resetGlobals() + interceptor := DebugLogInterceptor() + info := &grpc.UnaryServerInfo{FullMethod: "/test/Debug"} + + var capturedCtx context.Context + handler := func(ctx context.Context, req any) (any, error) { + capturedCtx = ctx + return "ok", nil + } + + _, err := interceptor(context.Background(), &debugRequest{debug: true}, info, handler) + if err != nil { + t.Fatalf("unexpected error: %v", err) + } + level, found := log.GetOverridenLogLevel(capturedCtx) + if !found || level != loggers.DebugLevel { + t.Errorf("expected debug level override, found=%v level=%v", found, level) + } +} + +func TestDebugLogInterceptor_ProtoFieldEnableDebug(t *testing.T) { + resetGlobals() + interceptor := DebugLogInterceptor() + info := &grpc.UnaryServerInfo{FullMethod: "/test/Debug"} + + var capturedCtx context.Context + handler := func(ctx context.Context, req any) (any, error) { + capturedCtx = ctx + return "ok", nil + } + + _, err := interceptor(context.Background(), &enableDebugRequest{enable: true}, info, handler) + if err != nil { + t.Fatalf("unexpected error: %v", err) + } + level, found := log.GetOverridenLogLevel(capturedCtx) + if !found || level != loggers.DebugLevel { + t.Errorf("expected debug level override, found=%v level=%v", found, level) + } +} + +func TestDebugLogInterceptor_NoField(t *testing.T) { + resetGlobals() + interceptor := DebugLogInterceptor() + info := &grpc.UnaryServerInfo{FullMethod: "/test/NoDebug"} + + var capturedCtx context.Context + handler := func(ctx context.Context, req any) (any, error) { + capturedCtx = ctx + return "ok", nil + } + + _, err := interceptor(context.Background(), &plainRequest{}, info, handler) + if err != nil { + t.Fatalf("unexpected error: %v", err) + } + _, found := log.GetOverridenLogLevel(capturedCtx) + if found { + t.Error("expected no log level override for request without debug field") + } +} + +func TestDebugLogInterceptor_DebugFalse(t *testing.T) { + resetGlobals() + interceptor := DebugLogInterceptor() + info := &grpc.UnaryServerInfo{FullMethod: "/test/Debug"} + + var capturedCtx context.Context + handler := func(ctx context.Context, req any) (any, error) { + capturedCtx = ctx + return "ok", nil + } + + _, err := interceptor(context.Background(), &debugRequest{debug: false}, info, handler) + if err != nil { + t.Fatalf("unexpected error: %v", err) + } + _, found := log.GetOverridenLogLevel(capturedCtx) + if found { + t.Error("expected no log level override when debug=false") + } +} + +func TestDebugLogInterceptor_Metadata(t *testing.T) { + resetGlobals() + interceptor := DebugLogInterceptor() + info := &grpc.UnaryServerInfo{FullMethod: "/test/MetadataDebug"} + + md := grpcmd.New(map[string]string{"x-debug-log-level": "debug"}) + ctx := grpcmd.NewIncomingContext(context.Background(), md) + + var capturedCtx context.Context + handler := func(ctx context.Context, req any) (any, error) { + capturedCtx = ctx + return "ok", nil + } + + _, err := interceptor(ctx, &plainRequest{}, info, handler) + if err != nil { + t.Fatalf("unexpected error: %v", err) + } + level, found := log.GetOverridenLogLevel(capturedCtx) + if !found || level != loggers.DebugLevel { + t.Errorf("expected debug level from metadata, found=%v level=%v", found, level) + } +} + +func TestDebugLogInterceptor_CustomHeaderName(t *testing.T) { + resetGlobals() + SetDebugLogHeaderName("X-My-Debug") + interceptor := DebugLogInterceptor() + info := &grpc.UnaryServerInfo{FullMethod: "/test/CustomHeader"} + + md := grpcmd.New(map[string]string{"x-my-debug": "debug"}) + ctx := grpcmd.NewIncomingContext(context.Background(), md) + + var capturedCtx context.Context + handler := func(ctx context.Context, req any) (any, error) { + capturedCtx = ctx + return "ok", nil + } + + _, err := interceptor(ctx, &plainRequest{}, info, handler) + if err != nil { + t.Fatalf("unexpected error: %v", err) + } + level, found := log.GetOverridenLogLevel(capturedCtx) + if !found || level != loggers.DebugLevel { + t.Errorf("expected debug level from custom header, found=%v level=%v", found, level) + } +} + +func TestDebugLogInterceptor_Disabled(t *testing.T) { + resetGlobals() + SetDisableDebugLogInterceptor(true) + + ints := DefaultInterceptors() + for _, interceptor := range ints { + info := &grpc.UnaryServerInfo{FullMethod: "/test/Disabled"} + var capturedCtx context.Context + handler := func(ctx context.Context, req any) (any, error) { + capturedCtx = ctx + return "ok", nil + } + _, _ = interceptor(context.Background(), &debugRequest{debug: true}, info, handler) + if capturedCtx != nil { + if _, found := log.GetOverridenLogLevel(capturedCtx); found { + t.Error("expected no debug override when interceptor is disabled") + } + } + } +}