diff --git a/go.mod b/go.mod index d115962..8ac2247 100644 --- a/go.mod +++ b/go.mod @@ -5,7 +5,7 @@ go 1.25.8 require ( github.com/afex/hystrix-go v0.0.0-20180502004556-fa1af6a1f4f5 github.com/go-coldbrew/errors v0.2.6 - github.com/go-coldbrew/log v0.2.7 + github.com/go-coldbrew/log v0.2.8 github.com/go-coldbrew/options v0.2.6 github.com/go-coldbrew/tracing v0.2.0 github.com/grpc-ecosystem/go-grpc-middleware/providers/prometheus v1.1.0 @@ -93,8 +93,6 @@ require ( github.com/go-git/gcfg v1.5.1-0.20230307220236-3a3c6141e376 // indirect github.com/go-git/go-billy/v5 v5.8.0 // indirect github.com/go-git/go-git/v5 v5.17.1 // indirect - github.com/go-kit/log v0.2.1 // indirect - github.com/go-logfmt/logfmt v0.6.1 // indirect github.com/go-toolsmith/astcast v1.1.0 // indirect github.com/go-toolsmith/astcopy v1.1.0 // indirect github.com/go-toolsmith/astequal v1.2.0 // indirect diff --git a/go.sum b/go.sum index a377fdc..09fd9b0 100644 --- a/go.sum +++ b/go.sum @@ -171,8 +171,8 @@ 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.6 h1:rNOI+XcxuyrN/t3e7zDBVUVzcYBNmhyjatsnJg9MDZA= github.com/go-coldbrew/errors v0.2.6/go.mod h1:jFXeN7Q74fggbIEZu/68vhRX1ob2zfc+2sy0osVfBlY= -github.com/go-coldbrew/log v0.2.7 h1:kRQeTYLPLcjjAWuCcGZpNn8twSY/NbsGpjIKbpXEnRA= -github.com/go-coldbrew/log v0.2.7/go.mod h1:BB+2VecklLXTaDQdNNe2h3r5rSZL2DGvJBXAgrXq1dk= +github.com/go-coldbrew/log v0.2.8 h1:aF+vw23zMyh5S9vhhofERiaPpSDyeJH1Tv1CYREn/a0= +github.com/go-coldbrew/log v0.2.8/go.mod h1:RKvGzMZMt7FpQ9u36adkDigRxkOvRj1diwgAgRJZH4E= github.com/go-coldbrew/options v0.2.6 h1:Nr93v7PbO+EYLHhzA8biGumaTTSHLHqTYLg70n/foXE= github.com/go-coldbrew/options v0.2.6/go.mod h1:Os4pZwIgMHES079iOKXTlzcipWXbxw0OhsAN5D9m2mM= github.com/go-coldbrew/tracing v0.2.0 h1:WGfdp5PNunOGfjTZGXPFaip3G5qOOMP622JFYA90ML4= diff --git a/interceptors.go b/interceptors.go index 433426b..d20b77c 100644 --- a/interceptors.go +++ b/interceptors.go @@ -56,6 +56,7 @@ var ( streamClientInterceptors = []grpc.StreamClientInterceptor{} useCBClientInterceptors = true responseTimeLogLevel loggers.Level = loggers.InfoLevel + responseTimeLogErrorOnly bool srvMetricsOpts []grpcprom.ServerMetricsOption cltMetricsOpts []grpcprom.ClientMetricsOption srvMetricsOnce sync.Once @@ -70,6 +71,13 @@ func SetResponseTimeLogLevel(ctx context.Context, level loggers.Level) { responseTimeLogLevel = level } +// SetResponseTimeLogErrorOnly when set to true, only logs response time when +// the request returns an error. Successful requests are not logged. +// Must be called during initialization, before the server starts. Not safe for concurrent use. +func SetResponseTimeLogErrorOnly(errorOnly bool) { + responseTimeLogErrorOnly = errorOnly +} + // If it returns false, the given request will not be traced. type FilterFunc func(ctx context.Context, fullMethodName string) bool @@ -395,10 +403,10 @@ func DefaultClientStreamInterceptors(defaultOpts ...interface{}) []grpc.StreamCl ints = append(ints, streamClientInterceptors...) } if useCBClientInterceptors { - ints = append(ints, - nrgrpc.StreamClientInterceptor, - getClientMetrics().StreamClientInterceptor(), - ) + if nrutil.GetNewRelicApp() != nil { + ints = append(ints, nrgrpc.StreamClientInterceptor) + } + ints = append(ints, getClientMetrics().StreamClientInterceptor()) } return ints } @@ -442,14 +450,16 @@ func DebugLoggingInterceptor() grpc.UnaryServerInterceptor { // ResponseTimeLoggingInterceptor logs response time for each request on server func ResponseTimeLoggingInterceptor(ff FilterFunc) grpc.UnaryServerInterceptor { return func(ctx context.Context, req interface{}, info *grpc.UnaryServerInfo, handler grpc.UnaryHandler) (resp interface{}, err error) { - ctx = options.AddToOptions(ctx, "", "") - ctx = loggers.AddToLogContext(ctx, "", "") ctx = loggers.AddToLogContext(ctx, "grpcMethod", info.FullMethod) defer func(ctx context.Context, method string, begin time.Time) { if ff != nil && !ff(ctx, method) { return } - logArgs := []any{"error", err, "took", time.Since(begin)} + if responseTimeLogErrorOnly && err == nil { + return + } + logArgs := make([]any, 0, 6) + logArgs = append(logArgs, "error", err, "took", time.Since(begin)) if err != nil { logArgs = append(logArgs, "grpcCode", status.Code(err)) } @@ -468,9 +478,17 @@ func OptionsInterceptor() grpc.UnaryServerInterceptor { } } -// NewRelicInterceptor intercepts all server actions and reports them to newrelic +// NewRelicInterceptor intercepts all server actions and reports them to newrelic. +// When NewRelic app is nil (no license key configured), returns a pass-through +// interceptor to avoid overhead. func NewRelicInterceptor() grpc.UnaryServerInterceptor { - nrh := nrgrpc.UnaryServerInterceptor(nrutil.GetNewRelicApp()) + app := nrutil.GetNewRelicApp() + if app == nil { + return func(ctx context.Context, req interface{}, info *grpc.UnaryServerInfo, handler grpc.UnaryHandler) (interface{}, error) { + return handler(ctx, req) + } + } + nrh := nrgrpc.UnaryServerInterceptor(app) return func(ctx context.Context, req interface{}, info *grpc.UnaryServerInfo, handler grpc.UnaryHandler) (resp interface{}, err error) { if defaultFilterFunc(ctx, info.FullMethod) { return nrh(ctx, req, info, handler) @@ -522,8 +540,16 @@ func PanicRecoveryInterceptor() grpc.UnaryServerInterceptor { } } -// NewRelicClientInterceptor intercepts all client actions and reports them to newrelic +// NewRelicClientInterceptor intercepts all client actions and reports them to newrelic. +// When NewRelic app is nil (no license key configured), returns a pass-through +// interceptor to avoid overhead. func NewRelicClientInterceptor() grpc.UnaryClientInterceptor { + app := nrutil.GetNewRelicApp() + if app == nil { + return func(ctx context.Context, method string, req, reply interface{}, cc *grpc.ClientConn, invoker grpc.UnaryInvoker, opts ...grpc.CallOption) error { + return invoker(ctx, method, req, reply, cc, opts...) + } + } return func(ctx context.Context, method string, req, reply interface{}, cc *grpc.ClientConn, invoker grpc.UnaryInvoker, opts ...grpc.CallOption) error { if defaultFilterFunc(ctx, method) { return nrgrpc.UnaryClientInterceptor(ctx, method, req, reply, cc, invoker, opts...) @@ -611,7 +637,11 @@ func HystrixClientInterceptor(defaultOpts ...grpc.CallOption) grpc.UnaryClientIn func ResponseTimeLoggingStreamInterceptor() grpc.StreamServerInterceptor { return func(srv interface{}, stream grpc.ServerStream, info *grpc.StreamServerInfo, handler grpc.StreamHandler) (err error) { defer func(begin time.Time) { - logArgs := []any{"method", info.FullMethod, "error", err, "took", time.Since(begin)} + if responseTimeLogErrorOnly && err == nil { + return + } + logArgs := make([]any, 0, 8) + logArgs = append(logArgs, "method", info.FullMethod, "error", err, "took", time.Since(begin)) if err != nil { logArgs = append(logArgs, "grpcCode", status.Code(err)) } diff --git a/interceptors_test.go b/interceptors_test.go index 95c817a..ae736a0 100644 --- a/interceptors_test.go +++ b/interceptors_test.go @@ -2,11 +2,13 @@ package interceptors import ( "context" + "errors" "fmt" "net/http" "sync" "testing" + "github.com/go-coldbrew/log/loggers" "github.com/grpc-ecosystem/grpc-gateway/v2/runtime" "google.golang.org/grpc" grpcmd "google.golang.org/grpc/metadata" @@ -37,6 +39,8 @@ func resetGlobals() { unaryClientInterceptors = []grpc.UnaryClientInterceptor{} streamClientInterceptors = []grpc.StreamClientInterceptor{} useCBClientInterceptors = true + responseTimeLogErrorOnly = false + responseTimeLogLevel = loggers.InfoLevel } func TestFilterMethodsFunc(t *testing.T) { @@ -630,3 +634,105 @@ func BenchmarkFilterMethodsFunc(b *testing.B) { } }) } + +// noopHandler is a handler that returns immediately with no error. +var noopHandler grpc.UnaryHandler = func(ctx context.Context, req interface{}) (interface{}, error) { + return "ok", nil +} + +// errHandler is a handler that returns an error. +var errHandler grpc.UnaryHandler = func(ctx context.Context, req interface{}) (interface{}, error) { + return nil, errors.New("test error") +} + +var benchInfo = &grpc.UnaryServerInfo{FullMethod: "/test.Service/Method"} + +func BenchmarkNewRelicInterceptor_NilApp(b *testing.B) { + // NR app is nil by default (no license key). The interceptor should + // be a direct pass-through with zero overhead. + resetGlobals() + interceptor := NewRelicInterceptor() + ctx := grpcContext() + + b.ResetTimer() + b.ReportAllocs() + for b.Loop() { + interceptor(ctx, nil, benchInfo, noopHandler) + } +} + +func BenchmarkResponseTimeLogging(b *testing.B) { + resetGlobals() + // Use debug level — the slog default logger discards debug, so we + // measure interceptor + log-args-building overhead without I/O noise. + responseTimeLogLevel = loggers.DebugLevel + ctx := grpcContext() + ff := FilterMethodsFunc + + b.Run("default/success", func(b *testing.B) { + responseTimeLogErrorOnly = false + interceptor := ResponseTimeLoggingInterceptor(ff) + b.ResetTimer() + b.ReportAllocs() + for b.Loop() { + interceptor(ctx, nil, benchInfo, noopHandler) + } + }) + + b.Run("default/error", func(b *testing.B) { + responseTimeLogErrorOnly = false + interceptor := ResponseTimeLoggingInterceptor(ff) + b.ResetTimer() + b.ReportAllocs() + for b.Loop() { + interceptor(ctx, nil, benchInfo, errHandler) + } + }) + + b.Run("error_only/success", func(b *testing.B) { + responseTimeLogErrorOnly = true + interceptor := ResponseTimeLoggingInterceptor(ff) + b.ResetTimer() + b.ReportAllocs() + for b.Loop() { + interceptor(ctx, nil, benchInfo, noopHandler) + } + }) + + b.Run("error_only/error", func(b *testing.B) { + responseTimeLogErrorOnly = true + interceptor := ResponseTimeLoggingInterceptor(ff) + b.ResetTimer() + b.ReportAllocs() + for b.Loop() { + interceptor(ctx, nil, benchInfo, errHandler) + } + }) + + // Restore default. + responseTimeLogErrorOnly = false +} + +func BenchmarkDefaultInterceptors(b *testing.B) { + resetGlobals() + ctx := grpcContext() + chain := DefaultInterceptors() + + // Build a chained handler that applies all interceptors. + var chainedHandler grpc.UnaryHandler = noopHandler + for i := len(chain) - 1; i >= 0; i-- { + next := chainedHandler + interceptor := chain[i] + chainedHandler = func(ctx context.Context, req interface{}) (interface{}, error) { + return interceptor(ctx, req, benchInfo, func(ctx context.Context, req interface{}) (interface{}, error) { + return next(ctx, req) + }) + } + } + + b.ResetTimer() + b.ReportAllocs() + for b.Loop() { + chainedHandler(ctx, nil) + } +}