From 0f07c31c16efc59f0ac8f69fe0bf8bd125fa9ed0 Mon Sep 17 00:00:00 2001 From: Bryan Boreham Date: Thu, 13 Jul 2023 10:37:40 +0000 Subject: [PATCH 1/8] middleware: add a way to stop errors being logged E.g. if the error is caused by overload, then we don't want to log it because that uses more resource. Signed-off-by: Bryan Boreham --- middleware/grpc_logging.go | 4 ++++ middleware/logging.go | 11 +++++++++++ middleware/logging_test.go | 6 ++++++ 3 files changed, 21 insertions(+) diff --git a/middleware/grpc_logging.go b/middleware/grpc_logging.go index 59994413..e5b0e670 100644 --- a/middleware/grpc_logging.go +++ b/middleware/grpc_logging.go @@ -1,6 +1,7 @@ package middleware import ( + "errors" "time" "golang.org/x/net/context" @@ -31,6 +32,9 @@ func (s GRPCServerLog) UnaryServerInterceptor(ctx context.Context, req interface if err == nil && s.DisableRequestSuccessLog { return resp, nil } + if errors.Is(err, DoNotLogError{}) { + return resp, err + } entry := user.LogWith(ctx, s.Log).WithFields(logging.Fields{"method": info.FullMethod, "duration": time.Since(begin)}) if err != nil { diff --git a/middleware/logging.go b/middleware/logging.go index fcb8453f..9474eff3 100644 --- a/middleware/logging.go +++ b/middleware/logging.go @@ -46,6 +46,14 @@ func NewLogMiddleware(log logging.Interface, logRequestHeaders bool, logRequestA } } +// This can be used with `errors.Is` to see if the error marked itself as not to be logged. +// E.g. if the error is caused by overload, then we don't want to log it because that uses more resource. +type DoNotLogError struct{ Err error } + +func (i DoNotLogError) Error() string { return i.Err.Error() } +func Unwrap(i DoNotLogError) error { return i.Err } +func (i DoNotLogError) Is(target error) bool { _, ok := target.(DoNotLogError); return ok } + // logWithRequest information from the request and context as fields. func (l Log) logWithRequest(r *http.Request) logging.Interface { localLog := l.Log @@ -83,6 +91,9 @@ func (l Log) Wrap(next http.Handler) http.Handler { statusCode, writeErr := wrapped.getStatusCode(), wrapped.getWriteError() if writeErr != nil { + if errors.Is(writeErr, DoNotLogError{}) { + return + } if errors.Is(writeErr, context.Canceled) { if l.LogRequestAtInfoLevel { requestLog.Infof("%s %s %s, request cancelled: %s ws: %v; %s", r.Method, uri, time.Since(begin), writeErr, IsWSHandshakeRequest(r), headers) diff --git a/middleware/logging_test.go b/middleware/logging_test.go index c282064c..f9b2883e 100644 --- a/middleware/logging_test.go +++ b/middleware/logging_test.go @@ -28,6 +28,9 @@ func TestBadWriteLogging(t *testing.T) { }, { err: nil, logContains: []string{"debug", "GET http://example.com/foo (200)"}, + }, { + err: DoNotLogError{Err: errors.New("yolo")}, + logContains: nil, }} { buf := bytes.NewBuffer(nil) logrusLogger := logrus.New() @@ -51,6 +54,9 @@ func TestBadWriteLogging(t *testing.T) { } loggingHandler.ServeHTTP(w, req) + if len(tc.logContains) == 0 { + require.Empty(t, buf) + } for _, content := range tc.logContains { require.True(t, bytes.Contains(buf.Bytes(), []byte(content))) } From d1f8877b91ceb519aa82a624a27225bc033cdae3 Mon Sep 17 00:00:00 2001 From: Bryan Boreham Date: Fri, 14 Jul 2023 17:34:53 +0000 Subject: [PATCH 2/8] Duh Signed-off-by: Bryan Boreham --- middleware/logging.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/middleware/logging.go b/middleware/logging.go index 9474eff3..c3c00b99 100644 --- a/middleware/logging.go +++ b/middleware/logging.go @@ -51,7 +51,7 @@ func NewLogMiddleware(log logging.Interface, logRequestHeaders bool, logRequestA type DoNotLogError struct{ Err error } func (i DoNotLogError) Error() string { return i.Err.Error() } -func Unwrap(i DoNotLogError) error { return i.Err } +func (i DoNotLogError) Unwrap() error { return i.Err } func (i DoNotLogError) Is(target error) bool { _, ok := target.(DoNotLogError); return ok } // logWithRequest information from the request and context as fields. From 05847764eef7097001cd37b2f204570da4cfea4b Mon Sep 17 00:00:00 2001 From: Bryan Boreham Date: Tue, 25 Jul 2023 13:55:38 +0000 Subject: [PATCH 3/8] Add test for gRPC logging Patterned after the one for http logging. --- middleware/grpc_logging_test.go | 44 +++++++++++++++++++++++++++++++++ 1 file changed, 44 insertions(+) diff --git a/middleware/grpc_logging_test.go b/middleware/grpc_logging_test.go index 88de6d11..985b3b32 100644 --- a/middleware/grpc_logging_test.go +++ b/middleware/grpc_logging_test.go @@ -1,11 +1,14 @@ package middleware import ( + "bytes" "context" + "errors" "testing" "github.com/go-kit/log" "github.com/go-kit/log/level" + "github.com/stretchr/testify/require" "google.golang.org/grpc" "github.com/weaveworks/common/logging" @@ -28,3 +31,44 @@ func BenchmarkGRPCServerLog_UnaryServerInterceptor_NoError(b *testing.B) { _, _ = l.UnaryServerInterceptor(ctx, nil, info, handler) } } + +func TestGrpcLogging(t *testing.T) { + ctx := context.Background() + info := &grpc.UnaryServerInfo{FullMethod: "Test"} + for _, tc := range []struct { + err error + logContains []string + }{{ + err: context.Canceled, + logContains: []string{"level=debug", "context canceled"}, + }, { + err: errors.New("yolo"), + logContains: []string{"level=warn", "err=yolo"}, + }, { + err: nil, + logContains: []string{"level=debug", "method=Test"}, + }, { + err: DoNotLogError{Err: errors.New("yolo")}, + logContains: nil, + }} { + t.Run("", func(t *testing.T) { + buf := bytes.NewBuffer(nil) + logger := logging.GoKit(log.NewLogfmtLogger(buf)) + l := GRPCServerLog{Log: logger, WithRequest: true, DisableRequestSuccessLog: false} + + handler := func(ctx context.Context, req interface{}) (interface{}, error) { + return nil, tc.err + } + + _, err := l.UnaryServerInterceptor(ctx, nil, info, handler) + require.ErrorIs(t, tc.err, err) + + if len(tc.logContains) == 0 { + require.Empty(t, buf) + } + for _, content := range tc.logContains { + require.Contains(t, buf.String(), content) + } + }) + } +} From 6b10c7bfb8aa42a439861993434cd509c5819dfc Mon Sep 17 00:00:00 2001 From: Bryan Boreham Date: Tue, 25 Jul 2023 14:06:42 +0000 Subject: [PATCH 4/8] Move DoNotLogError to grpc_logging Http doesn't have access to the error that caused a failure, so it was an error to try to change behaviour on them. --- middleware/grpc_logging.go | 8 ++++++++ middleware/logging.go | 11 ----------- middleware/logging_test.go | 3 --- 3 files changed, 8 insertions(+), 14 deletions(-) diff --git a/middleware/grpc_logging.go b/middleware/grpc_logging.go index e5b0e670..f84aae9d 100644 --- a/middleware/grpc_logging.go +++ b/middleware/grpc_logging.go @@ -17,6 +17,14 @@ const ( errorKey = "err" ) +// This can be used with `errors.Is` to see if the error marked itself as not to be logged. +// E.g. if the error is caused by overload, then we don't want to log it because that uses more resource. +type DoNotLogError struct{ Err error } + +func (i DoNotLogError) Error() string { return i.Err.Error() } +func (i DoNotLogError) Unwrap() error { return i.Err } +func (i DoNotLogError) Is(target error) bool { _, ok := target.(DoNotLogError); return ok } + // GRPCServerLog logs grpc requests, errors, and latency. type GRPCServerLog struct { Log logging.Interface diff --git a/middleware/logging.go b/middleware/logging.go index c3c00b99..fcb8453f 100644 --- a/middleware/logging.go +++ b/middleware/logging.go @@ -46,14 +46,6 @@ func NewLogMiddleware(log logging.Interface, logRequestHeaders bool, logRequestA } } -// This can be used with `errors.Is` to see if the error marked itself as not to be logged. -// E.g. if the error is caused by overload, then we don't want to log it because that uses more resource. -type DoNotLogError struct{ Err error } - -func (i DoNotLogError) Error() string { return i.Err.Error() } -func (i DoNotLogError) Unwrap() error { return i.Err } -func (i DoNotLogError) Is(target error) bool { _, ok := target.(DoNotLogError); return ok } - // logWithRequest information from the request and context as fields. func (l Log) logWithRequest(r *http.Request) logging.Interface { localLog := l.Log @@ -91,9 +83,6 @@ func (l Log) Wrap(next http.Handler) http.Handler { statusCode, writeErr := wrapped.getStatusCode(), wrapped.getWriteError() if writeErr != nil { - if errors.Is(writeErr, DoNotLogError{}) { - return - } if errors.Is(writeErr, context.Canceled) { if l.LogRequestAtInfoLevel { requestLog.Infof("%s %s %s, request cancelled: %s ws: %v; %s", r.Method, uri, time.Since(begin), writeErr, IsWSHandshakeRequest(r), headers) diff --git a/middleware/logging_test.go b/middleware/logging_test.go index f9b2883e..1cd7aa1b 100644 --- a/middleware/logging_test.go +++ b/middleware/logging_test.go @@ -28,9 +28,6 @@ func TestBadWriteLogging(t *testing.T) { }, { err: nil, logContains: []string{"debug", "GET http://example.com/foo (200)"}, - }, { - err: DoNotLogError{Err: errors.New("yolo")}, - logContains: nil, }} { buf := bytes.NewBuffer(nil) logrusLogger := logrus.New() From 70276ee599a1db6e419c4c8d00f47cfae2be2d4d Mon Sep 17 00:00:00 2001 From: Bryan Boreham Date: Tue, 25 Jul 2023 14:26:52 +0000 Subject: [PATCH 5/8] Make logging optional via a custom interface --- middleware/grpc_logging.go | 15 +++++++-------- middleware/grpc_logging_test.go | 11 ++++++++++- 2 files changed, 17 insertions(+), 9 deletions(-) diff --git a/middleware/grpc_logging.go b/middleware/grpc_logging.go index f84aae9d..8b20b0f4 100644 --- a/middleware/grpc_logging.go +++ b/middleware/grpc_logging.go @@ -17,13 +17,10 @@ const ( errorKey = "err" ) -// This can be used with `errors.Is` to see if the error marked itself as not to be logged. -// E.g. if the error is caused by overload, then we don't want to log it because that uses more resource. -type DoNotLogError struct{ Err error } - -func (i DoNotLogError) Error() string { return i.Err.Error() } -func (i DoNotLogError) Unwrap() error { return i.Err } -func (i DoNotLogError) Is(target error) bool { _, ok := target.(DoNotLogError); return ok } +// If an error implements this interface, it will get called and GRPCServerLog will do nothing. +type CustomLog interface { + LogOperation(ctx context.Context, _ logging.Interface, method string, duration time.Duration) +} // GRPCServerLog logs grpc requests, errors, and latency. type GRPCServerLog struct { @@ -40,7 +37,9 @@ func (s GRPCServerLog) UnaryServerInterceptor(ctx context.Context, req interface if err == nil && s.DisableRequestSuccessLog { return resp, nil } - if errors.Is(err, DoNotLogError{}) { + var customLog CustomLog + if errors.As(err, &customLog) { + customLog.LogOperation(ctx, s.Log, info.FullMethod, time.Since(begin)) return resp, err } diff --git a/middleware/grpc_logging_test.go b/middleware/grpc_logging_test.go index 985b3b32..8d4a66fd 100644 --- a/middleware/grpc_logging_test.go +++ b/middleware/grpc_logging_test.go @@ -5,6 +5,7 @@ import ( "context" "errors" "testing" + "time" "github.com/go-kit/log" "github.com/go-kit/log/level" @@ -32,6 +33,14 @@ func BenchmarkGRPCServerLog_UnaryServerInterceptor_NoError(b *testing.B) { } } +type doNotLogError struct{ Err error } + +func (i doNotLogError) Error() string { return i.Err.Error() } +func (i doNotLogError) Unwrap() error { return i.Err } +func (i doNotLogError) LogOperation(_ context.Context, _ logging.Interface, _ string, _ time.Duration) { + // no-op +} + func TestGrpcLogging(t *testing.T) { ctx := context.Background() info := &grpc.UnaryServerInfo{FullMethod: "Test"} @@ -48,7 +57,7 @@ func TestGrpcLogging(t *testing.T) { err: nil, logContains: []string{"level=debug", "method=Test"}, }, { - err: DoNotLogError{Err: errors.New("yolo")}, + err: doNotLogError{Err: errors.New("yolo")}, logContains: nil, }} { t.Run("", func(t *testing.T) { From 1bc5241d8104d06af33d3c7865313e2b1f9a5a19 Mon Sep 17 00:00:00 2001 From: Bryan Boreham Date: Tue, 25 Jul 2023 14:29:45 +0000 Subject: [PATCH 6/8] Undo change to logging test It's not used now. --- middleware/logging_test.go | 3 --- 1 file changed, 3 deletions(-) diff --git a/middleware/logging_test.go b/middleware/logging_test.go index 1cd7aa1b..c282064c 100644 --- a/middleware/logging_test.go +++ b/middleware/logging_test.go @@ -51,9 +51,6 @@ func TestBadWriteLogging(t *testing.T) { } loggingHandler.ServeHTTP(w, req) - if len(tc.logContains) == 0 { - require.Empty(t, buf) - } for _, content := range tc.logContains { require.True(t, bytes.Contains(buf.Bytes(), []byte(content))) } From 70dc704e0cb87e3dd82b5943022cb1e8b69a2e2c Mon Sep 17 00:00:00 2001 From: Bryan Boreham Date: Tue, 25 Jul 2023 14:54:21 +0000 Subject: [PATCH 7/8] Name change suggested by colega --- middleware/grpc_logging.go | 12 ++++++------ middleware/grpc_logging_test.go | 2 +- 2 files changed, 7 insertions(+), 7 deletions(-) diff --git a/middleware/grpc_logging.go b/middleware/grpc_logging.go index 8b20b0f4..5ea9f9cc 100644 --- a/middleware/grpc_logging.go +++ b/middleware/grpc_logging.go @@ -17,9 +17,9 @@ const ( errorKey = "err" ) -// If an error implements this interface, it will get called and GRPCServerLog will do nothing. -type CustomLog interface { - LogOperation(ctx context.Context, _ logging.Interface, method string, duration time.Duration) +// If an error implements Observe(), it will get called and GRPCServerLog will do nothing. +type Observer interface { + Observe(ctx context.Context, _ logging.Interface, method string, duration time.Duration) } // GRPCServerLog logs grpc requests, errors, and latency. @@ -37,9 +37,9 @@ func (s GRPCServerLog) UnaryServerInterceptor(ctx context.Context, req interface if err == nil && s.DisableRequestSuccessLog { return resp, nil } - var customLog CustomLog - if errors.As(err, &customLog) { - customLog.LogOperation(ctx, s.Log, info.FullMethod, time.Since(begin)) + var observer Observer + if errors.As(err, &observer) { + observer.Observe(ctx, s.Log, info.FullMethod, time.Since(begin)) return resp, err } diff --git a/middleware/grpc_logging_test.go b/middleware/grpc_logging_test.go index 8d4a66fd..33712ca0 100644 --- a/middleware/grpc_logging_test.go +++ b/middleware/grpc_logging_test.go @@ -37,7 +37,7 @@ type doNotLogError struct{ Err error } func (i doNotLogError) Error() string { return i.Err.Error() } func (i doNotLogError) Unwrap() error { return i.Err } -func (i doNotLogError) LogOperation(_ context.Context, _ logging.Interface, _ string, _ time.Duration) { +func (i doNotLogError) Observe(_ context.Context, _ logging.Interface, _ string, _ time.Duration) { // no-op } From 9927ce6214595c3c1f2b51f5727e2fb29d2342ed Mon Sep 17 00:00:00 2001 From: Bryan Boreham Date: Wed, 26 Jul 2023 07:37:00 +0000 Subject: [PATCH 8/8] OptionalLogging interface with method ShouldLog Signed-off-by: Bryan Boreham --- middleware/grpc_logging.go | 11 +++++------ middleware/grpc_logging_test.go | 8 +++----- 2 files changed, 8 insertions(+), 11 deletions(-) diff --git a/middleware/grpc_logging.go b/middleware/grpc_logging.go index 5ea9f9cc..66aa8e22 100644 --- a/middleware/grpc_logging.go +++ b/middleware/grpc_logging.go @@ -17,9 +17,9 @@ const ( errorKey = "err" ) -// If an error implements Observe(), it will get called and GRPCServerLog will do nothing. -type Observer interface { - Observe(ctx context.Context, _ logging.Interface, method string, duration time.Duration) +// An error can implement ShouldLog() to control whether GRPCServerLog will log. +type OptionalLogging interface { + ShouldLog(ctx context.Context, duration time.Duration) bool } // GRPCServerLog logs grpc requests, errors, and latency. @@ -37,9 +37,8 @@ func (s GRPCServerLog) UnaryServerInterceptor(ctx context.Context, req interface if err == nil && s.DisableRequestSuccessLog { return resp, nil } - var observer Observer - if errors.As(err, &observer) { - observer.Observe(ctx, s.Log, info.FullMethod, time.Since(begin)) + var optional OptionalLogging + if errors.As(err, &optional) && !optional.ShouldLog(ctx, time.Since(begin)) { return resp, err } diff --git a/middleware/grpc_logging_test.go b/middleware/grpc_logging_test.go index 33712ca0..68d375ae 100644 --- a/middleware/grpc_logging_test.go +++ b/middleware/grpc_logging_test.go @@ -35,11 +35,9 @@ func BenchmarkGRPCServerLog_UnaryServerInterceptor_NoError(b *testing.B) { type doNotLogError struct{ Err error } -func (i doNotLogError) Error() string { return i.Err.Error() } -func (i doNotLogError) Unwrap() error { return i.Err } -func (i doNotLogError) Observe(_ context.Context, _ logging.Interface, _ string, _ time.Duration) { - // no-op -} +func (i doNotLogError) Error() string { return i.Err.Error() } +func (i doNotLogError) Unwrap() error { return i.Err } +func (i doNotLogError) ShouldLog(_ context.Context, _ time.Duration) bool { return false } func TestGrpcLogging(t *testing.T) { ctx := context.Background()