Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Avoid expensive log.Valuer evaluation for disallowed level #5297

Merged
merged 2 commits into from
May 10, 2023
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
1 change: 1 addition & 0 deletions CHANGELOG.md
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down
35 changes: 20 additions & 15 deletions pkg/util/log/log.go
Original file line number Diff line number Diff line change
Expand Up @@ -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 <autogenerated> 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.
Expand All @@ -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) {
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This is not being used anymore?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This is used by other packages.

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.
Expand Down
36 changes: 36 additions & 0 deletions pkg/util/log/log_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -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"
)

Expand Down Expand Up @@ -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)
}
}