diff --git a/CHANGELOG.md b/CHANGELOG.md index fd7ef1a629..19ceaf5be3 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -9,6 +9,7 @@ * [ENHANCEMENT] Support object storage backends for runtime configuration file. #5292 * [ENHANCEMENT] Query Frontend: Reject subquery with too small step size. #5323 * [ENHANCEMENT] Compactor: Exposing Thanos accept-malformed-index to Cortex compactor. #5334 +* [ENHANCEMENT] Log: Avoid expensive log.Valuer evaluation for disallowed levels. #5297 * [BUGFIX] Ruler: Validate if rule group can be safely converted back to rule group yaml from protobuf message #5265 * [BUGFIX] Querier: Convert gRPC `ResourceExhausted` status code from store gateway to 422 limit error. #5286 * [BUGFIX] Alertmanager: Route web-ui requests to the alertmanager distributor when sharding is enabled. #5293 diff --git a/pkg/util/log/log.go b/pkg/util/log/log.go index b2ca8724f7..a195954457 100644 --- a/pkg/util/log/log.go +++ b/pkg/util/log/log.go @@ -49,19 +49,16 @@ func init() { // InitLogger initialises the global gokit logger (util_log.Logger) and overrides the // default logger for the server. func InitLogger(cfg *server.Config) { - l, err := NewPrometheusLogger(cfg.LogLevel, cfg.LogFormat) - if err != nil { - panic(err) - } + l := newLoggerWithFormat(cfg.LogFormat) - // when use util_log.Logger, skip 3 stack frames. - Logger = log.With(l, "caller", log.Caller(3)) + // when use util_log.Logger, skip 6 stack frames. + Logger = newPrometheusLoggerFrom(l, cfg.LogLevel, "caller", log.Caller(6)) - // cfg.Log wraps log function, skip 4 stack frames to get caller information. + // cfg.Log wraps log function, skip 7 stack frames to get caller information. // this works in go 1.12, but doesn't work in versions earlier. // it will always shows the wrapper function generated by compiler // marked in old versions. - cfg.Log = logging.GoKit(log.With(l, "caller", log.Caller(4))) + cfg.Log = logging.GoKit(newPrometheusLoggerFrom(l, cfg.LogLevel, "caller", log.Caller(7))) } // PrometheusLogger exposes Prometheus counters for each of go-kit's log levels. @@ -72,24 +69,32 @@ type PrometheusLogger struct { // NewPrometheusLogger creates a new instance of PrometheusLogger which exposes // Prometheus counters for various log levels. func NewPrometheusLogger(l logging.Level, format logging.Format) (log.Logger, error) { + logger := newLoggerWithFormat(format) + return newPrometheusLoggerFrom(logger, l), nil +} + +func newLoggerWithFormat(format logging.Format) log.Logger { logger := log.NewLogfmtLogger(log.NewSyncWriter(os.Stderr)) if format.String() == "json" { logger = log.NewJSONLogger(log.NewSyncWriter(os.Stderr)) } - logger = level.NewFilter(logger, LevelFilter(l.String())) + return logger +} + +func newPrometheusLoggerFrom(logger log.Logger, logLevel logging.Level, keyvals ...interface{}) log.Logger { + // Sort the logger chain to avoid expensive log.Valuer evaluation for disallowed level. + // Ref: https://github.com/go-kit/log/issues/14#issuecomment-945038252 + logger = log.With(logger, "ts", log.DefaultTimestampUTC) + logger = log.With(logger, keyvals...) + logger = level.NewFilter(logger, LevelFilter(logLevel.String())) // Initialise counters for all supported levels: for _, level := range supportedLevels { logMessages.WithLabelValues(level.String()) } - - logger = &PrometheusLogger{ + return &PrometheusLogger{ logger: logger, } - - // return a Logger without caller information, shouldn't use directly - logger = log.With(logger, "ts", log.DefaultTimestampUTC) - return logger, nil } // Log increments the appropriate Prometheus counter depending on the log level. diff --git a/pkg/util/log/log_test.go b/pkg/util/log/log_test.go index ec28373689..0401d4ce08 100644 --- a/pkg/util/log/log_test.go +++ b/pkg/util/log/log_test.go @@ -2,10 +2,14 @@ package log import ( "context" + "io" "net/http" + "os" "testing" + "github.com/go-kit/log/level" "github.com/stretchr/testify/require" + "github.com/weaveworks/common/server" "google.golang.org/grpc/metadata" ) @@ -63,3 +67,35 @@ func TestInjectHeadersIntoHTTPRequest(t *testing.T) { require.Equal(t, "ContentsOfTestHeader2", header2[0]) } + +func TestInitLogger(t *testing.T) { + stderr := os.Stderr + r, w, err := os.Pipe() + require.NoError(t, err) + os.Stderr = w + defer func() { os.Stderr = stderr }() + + cfg := &server.Config{} + require.NoError(t, cfg.LogLevel.Set("debug")) + InitLogger(cfg) + + level.Debug(Logger).Log("hello", "world") + cfg.Log.Debugf("%s %s", "hello", "world") + + require.NoError(t, w.Close()) + logs, err := io.ReadAll(r) + require.NoError(t, err) + require.Contains(t, string(logs), "caller=log_test.go:82 level=debug hello=world") + require.Contains(t, string(logs), "caller=log_test.go:83 level=debug msg=\"hello world\"") +} + +func BenchmarkDisallowedLogLevels(b *testing.B) { + cfg := &server.Config{} + require.NoError(b, cfg.LogLevel.Set("warn")) + InitLogger(cfg) + + for i := 0; i < b.N; i++ { + level.Info(Logger).Log("hello", "world", "number", i) + level.Debug(Logger).Log("hello", "world", "number", i) + } +}