Fixing review findings

Signed-off-by: Yuri Nikolic <[email protected]>

log/global.go

@@ -19,7 +19,3 @@ func Global() log.Logger {
 func SetGlobal(logger log.Logger) {
 	global = logger
 }
-
-func Log(keyvals ...interface{}) error {
-	return global.Log(keyvals...)
-}

log/gokit.go

@@ -5,21 +5,42 @@
 package log
 
 import (
+	"fmt"
 	"io"
 	"os"
 
 	"github.com/go-kit/log"
 	"github.com/go-kit/log/level"
 )
 
-// NewGoKitFormat creates a new log.Logger whose format can be "json" or "logfmt".
-func NewGoKitFormat(l Level, format string) log.Logger {
-	var logger log.Logger
+const (
+	LogfmtFormat = "logfmt"
+)
+
+// NewGoKit creates a new GoKit logger with the given level, format and writer.
+// If the given writer is nil, os.Stderr is used.
+// If the given format is nil, logfmt is used.
+func NewGoKit(lvl Level, format string, writer io.Writer) log.Logger {
+	logger := newGoKit(format, writer)
+	return level.NewFilter(logger, lvl.Option)
+}
+
+func newGoKit(format string, writer io.Writer) log.Logger {
+	if writer == nil {
+		writer = log.NewSyncWriter(os.Stderr)
+	}
 	if format == "json" {
-		logger = log.NewJSONLogger(log.NewSyncWriter(os.Stderr))
-	} else {
-		logger = log.NewLogfmtLogger(log.NewSyncWriter(os.Stderr))
+		return log.NewJSONLogger(writer)
 	}
+	return log.NewLogfmtLogger(writer)
+}
+
+// NewGoKitWithFields creates a new GoKit logger with the given level and writer,
+// enriched with the "ts" and the "caller" fields for test purposes.
+// The "logfmt" format is used.
+// If the given writer is nil, os.Stderr is used.
+func NewGoKitWithFields(l Level, writer io.Writer) log.Logger {
+	logger := newGoKit(LogfmtFormat, writer)
 	return addStandardFields(logger, l)
 }
 
@@ -29,13 +50,24 @@ func addStandardFields(logger log.Logger, l Level) log.Logger {
 	return level.NewFilter(logger, l.Option)
 }
 
-// NewGoKit creates a new GoKit logger with the "logfmt" format.
-func NewGoKit(l Level) log.Logger {
-	return NewGoKitFormat(l, "logfmt")
+type lazySprintf interface {
+	String() string
 }
 
-// NewGoKitWriter creates a new GoKit logger with the passed level and writer.
-func NewGoKitWriter(l Level, writer io.Writer) log.Logger {
-	logger := log.NewLogfmtLogger(writer)
-	return addStandardFields(logger, l)
+type gokitLazySprintf struct {
+	format  string
+	args    []interface{}
+	sprintf func(string, ...any) string
+}
+
+func NewGokitLazySprintf(format string, args []interface{}) lazySprintf {
+	return &gokitLazySprintf{
+		format:  format,
+		args:    args,
+		sprintf: fmt.Sprintf,
+	}
+}
+
+func (s *gokitLazySprintf) String() string {
+	return s.sprintf(s.format, s.args...)
 }

log/gokit_test.go

@@ -5,11 +5,14 @@
 package log
 
 import (
+	"bytes"
 	"fmt"
 	"testing"
+	"time"
 
 	"github.com/go-kit/log"
 	"github.com/go-kit/log/level"
+	"github.com/stretchr/testify/require"
 )
 
 func BenchmarkDebugf(b *testing.B) {
@@ -28,3 +31,63 @@ func BenchmarkDebugf(b *testing.B) {
 		level.Debug(logger).Log("msg", fmt.Sprintf("%s %s (%d) %v", method, uri, statusCode, duration))
 	}
 }
+
+func TestSprintf(t *testing.T) {
+	tests := map[string]struct {
+		id     int
+		lvl    string
+		format string
+	}{
+		"debug level should log debug messages and call Sprintf": {
+			id:     1,
+			lvl:    "debug",
+			format: "debug %d has been logged %v",
+		},
+		"info level should not log debug messages and should not call Sprintf": {
+			id:     2,
+			lvl:    "info",
+			format: "info %d has not been logged %v",
+		},
+	}
+
+	buf := bytes.NewBuffer(nil)
+
+	for _, test := range tests {
+		var lvl Level
+		require.NoError(t, lvl.Set(test.lvl))
+		buf.Reset()
+		logger := NewGoKitWithFields(lvl, buf)
+		now := time.Now()
+		expectedMessage := fmt.Sprintf(test.format, test.id, now)
+		lazySprintf := newFakeGokitLazySprintf("debug %d has been logged %v", []interface{}{test.id, now})
+		level.Debug(logger).Log("msg", lazySprintf)
+		if test.lvl == "debug" {
+			require.True(t, bytes.Contains(buf.Bytes(), []byte(expectedMessage)))
+			require.Equal(t, 1, lazySprintf.countSprintf)
+		} else {
+			require.False(t, bytes.Contains(buf.Bytes(), []byte(expectedMessage)))
+			require.Equal(t, 0, lazySprintf.countSprintf)
+		}
+	}
+}
+
+type fakeGokitLazySprintf struct {
+	next         gokitLazySprintf
+	countSprintf int
+}
+
+func newFakeGokitLazySprintf(format string, args []interface{}) *fakeGokitLazySprintf {
+	return &fakeGokitLazySprintf{
+		gokitLazySprintf{
+			format:  format,
+			args:    args,
+			sprintf: fmt.Sprintf,
+		},
+		0,
+	}
+}
+
+func (f *fakeGokitLazySprintf) String() string {
+	f.countSprintf++
+	return f.next.String()
+}

log/logging.go

@@ -24,7 +24,7 @@ func Setup(logLevel string) error {
 		return err
 	}*/
 
-	logger := NewGoKitWriter(level, os.Stderr)
+	logger := NewGoKit(level, "logfmt", os.Stderr)
 	SetGlobal(logger)
 	return nil
 }

middleware/grpc_logging.go

@@ -7,11 +7,13 @@ package middleware
 import (
 	"context"
 	"errors"
-	"fmt"
 	"time"
 
 	"github.com/go-kit/log"
 	"github.com/go-kit/log/level"
+
+	dskit_log "github.com/grafana/dskit/log"
+
 	"google.golang.org/grpc"
 
 	grpcUtils "github.com/grafana/dskit/grpcutil"
@@ -60,7 +62,8 @@ func (s GRPCServerLog) UnaryServerInterceptor(ctx context.Context, req interface
 			level.Warn(entry).Log("msg", gRPC)
 		}
 	} else {
-		level.Debug(entry).Log("msg", fmt.Sprintf("%s (success)", gRPC))
+		lazySprintf := dskit_log.NewGokitLazySprintf("%s (success)", []interface{}{gRPC})
+		level.Debug(entry).Log("msg", lazySprintf)
 	}
 	return resp, err
 }
@@ -82,7 +85,8 @@ func (s GRPCServerLog) StreamServerInterceptor(srv interface{}, ss grpc.ServerSt
 			level.Warn(entry).Log("msg", gRPC)
 		}
 	} else {
-		level.Debug(entry).Log("msg", fmt.Sprintf("%s (success)", gRPC))
+		lazySprintf := dskit_log.NewGokitLazySprintf("%s (success)", []interface{}{gRPC})
+		level.Debug(entry).Log("msg", lazySprintf)
 	}
 	return err
 }

middleware/logging.go

@@ -8,7 +8,6 @@ import (
 	"bytes"
 	"context"
 	"errors"
-	"fmt"
 	"net/http"
 	"time"
 
@@ -82,7 +81,7 @@ func (l Log) Wrap(next http.Handler) http.Handler {
 		headers, err := dumpRequest(r, l.HTTPHeadersToExclude)
 		if err != nil {
 			headers = nil
-			level.Error(requestLog).Log("err", fmt.Sprintf("could not dump request headers: %v", err))
+			level.Error(requestLog).Log("msg", "could not dump request headers", "err", err)
 		}
 		var buf bytes.Buffer
 		wrapped := newBadResponseLoggingWriter(w, &buf)
@@ -93,12 +92,15 @@ func (l Log) Wrap(next http.Handler) http.Handler {
 		if writeErr != nil {
 			if errors.Is(writeErr, context.Canceled) {
 				if l.LogRequestAtInfoLevel {
-					level.Info(requestLog).Log("msg", fmt.Sprintf("%s %s %s, request cancelled: %s ws: %v; %s", r.Method, uri, time.Since(begin), writeErr, IsWSHandshakeRequest(r), headers))
+					lazySprintf := dskit_log.NewGokitLazySprintf("%s %s %s, request cancelled: %s ws: %v; %s", []interface{}{r.Method, uri, time.Since(begin), writeErr, IsWSHandshakeRequest(r), headers})
+					level.Info(requestLog).Log("msg", lazySprintf)
 				} else {
-					level.Debug(requestLog).Log("msg", fmt.Sprintf("%s %s %s, request cancelled: %s ws: %v; %s", r.Method, uri, time.Since(begin), writeErr, IsWSHandshakeRequest(r), headers))
+					lazySprintf := dskit_log.NewGokitLazySprintf("%s %s %s, request cancelled: %s ws: %v; %s", []interface{}{r.Method, uri, time.Since(begin), writeErr, IsWSHandshakeRequest(r), headers})
+					level.Debug(requestLog).Log("msg", lazySprintf)
 				}
 			} else {
-				level.Warn(requestLog).Log("msg", fmt.Sprintf("%s %s %s, error: %s ws: %v; %s", r.Method, uri, time.Since(begin), writeErr, IsWSHandshakeRequest(r), headers))
+				lazySprintf := dskit_log.NewGokitLazySprintf("%s %s %s, error: %s ws: %v; %s", []interface{}{r.Method, uri, time.Since(begin), writeErr, IsWSHandshakeRequest(r), headers})
+				level.Warn(requestLog).Log("msg", lazySprintf)
 			}
 
 			return
@@ -112,19 +114,24 @@ func (l Log) Wrap(next http.Handler) http.Handler {
 		case 100 <= statusCode && statusCode < 500 || statusCode == http.StatusBadGateway || statusCode == http.StatusServiceUnavailable:
 			if l.LogRequestAtInfoLevel {
 				if l.LogRequestHeaders && headers != nil {
-					level.Info(requestLog).Log("msg", fmt.Sprintf("%s %s (%d) %s ws: %v; %s", r.Method, uri, statusCode, time.Since(begin), IsWSHandshakeRequest(r), string(headers)))
+					lazySprintf := dskit_log.NewGokitLazySprintf("%s %s (%d) %s ws: %v; %s", []interface{}{r.Method, uri, statusCode, time.Since(begin), IsWSHandshakeRequest(r), string(headers)})
+					level.Info(requestLog).Log("msg", lazySprintf)
 				} else {
-					level.Info(requestLog).Log("msg", fmt.Sprintf("%s %s (%d) %s", r.Method, uri, statusCode, time.Since(begin)))
+					lazySprintf := dskit_log.NewGokitLazySprintf("%s %s (%d) %s", []interface{}{r.Method, uri, statusCode, time.Since(begin)})
+					level.Info(requestLog).Log("msg", lazySprintf)
 				}
 			} else {
 				if l.LogRequestHeaders && headers != nil {
-					level.Debug(requestLog).Log("msg", fmt.Sprintf("%s %s (%d) %s ws: %v; %s", r.Method, uri, statusCode, time.Since(begin), IsWSHandshakeRequest(r), string(headers)))
+					lazySprintf := dskit_log.NewGokitLazySprintf("%s %s (%d) %s ws: %v; %s", []interface{}{r.Method, uri, statusCode, time.Since(begin), IsWSHandshakeRequest(r), string(headers)})
+					level.Debug(requestLog).Log("msg", lazySprintf)
 				} else {
-					level.Debug(requestLog).Log("msg", fmt.Sprintf("%s %s (%d) %s", r.Method, uri, statusCode, time.Since(begin)))
+					lazySprintf := dskit_log.NewGokitLazySprintf("%s %s (%d) %s", []interface{}{r.Method, uri, statusCode, time.Since(begin)})
+					level.Debug(requestLog).Log("msg", lazySprintf)
 				}
 			}
 		default:
-			level.Warn(requestLog).Log("msg", fmt.Sprintf("%s %s (%d) %s Response: %q ws: %v; %s", r.Method, uri, statusCode, time.Since(begin), buf.Bytes(), IsWSHandshakeRequest(r), headers))
+			lazySprintf := dskit_log.NewGokitLazySprintf("%s %s (%d) %s Response: %q ws: %v; %s", []interface{}{r.Method, uri, statusCode, time.Since(begin), buf.Bytes(), IsWSHandshakeRequest(r), headers})
+			level.Warn(requestLog).Log("msg", lazySprintf)
 		}
 	})
 }

middleware/logging_test.go

@@ -35,7 +35,7 @@ func TestBadWriteLogging(t *testing.T) {
 		buf := bytes.NewBuffer(nil)
 		var level log.Level
 		require.NoError(t, level.Set("debug"))
-		logger := log.NewGoKitWriter(level, buf)
+		logger := log.NewGoKitWithFields(level, buf)
 
 		loggingMiddleware := Log{
 			Log: logger,
@@ -80,7 +80,7 @@ func TestDisabledSuccessfulRequestsLogging(t *testing.T) {
 		require.NoError(t, level.Set("debug"))
 
 		loggingMiddleware := Log{
-			Log:                      log.NewGoKitWriter(level, buf),
+			Log:                      log.NewGoKitWithFields(level, buf),
 			DisableRequestSuccessLog: tc.disableLog,
 		}
 
@@ -125,7 +125,7 @@ func TestLoggingRequestsAtInfoLevel(t *testing.T) {
 		require.NoError(t, level.Set("debug"))
 
 		loggingMiddleware := Log{
-			Log:                   log.NewGoKitWriter(level, buf),
+			Log:                   log.NewGoKitWithFields(level, buf),
 			LogRequestAtInfoLevel: true,
 		}
 		handler := func(w http.ResponseWriter, r *http.Request) {
@@ -179,7 +179,7 @@ func TestLoggingRequestWithExcludedHeaders(t *testing.T) {
 			var level log.Level
 			require.NoError(t, level.Set("debug"))
 
-			loggingMiddleware := NewLogMiddleware(log.NewGoKitWriter(level, buf), true, false, nil, tc.excludeHeaderList)
+			loggingMiddleware := NewLogMiddleware(log.NewGoKitWithFields(level, buf), true, false, nil, tc.excludeHeaderList)
 
 			handler := func(w http.ResponseWriter, r *http.Request) {
 				_, _ = io.WriteString(w, "<html><body>Hello world!</body></html>")

middleware/path_rewrite.go

@@ -5,7 +5,6 @@
 package middleware
 
 import (
-	"fmt"
 	"net/http"
 	"net/url"
 	"regexp"
@@ -34,7 +33,8 @@ func (p pathRewrite) Wrap(next http.Handler) http.Handler {
 		r.URL.RawPath = p.regexp.ReplaceAllString(r.URL.EscapedPath(), p.replacement)
 		path, err := url.PathUnescape(r.URL.RawPath)
 		if err != nil {
-			level.Error(log.Global()).Log(fmt.Sprintf("got invalid url-encoded path %v after applying path rewrite %v: %v", r.URL.RawPath, p, err))
+			lazySprintf := log.NewGokitLazySprintf("got invalid url-encoded path %v after applying path rewrite %v: %v", []interface{}{r.URL.RawPath, p})
+			level.Error(log.Global()).Log("msg", lazySprintf, "err", err)
 			w.WriteHeader(http.StatusInternalServerError)
 			return
 		}