From 7852e6d8ef25bf997cb2102eee596bc6804b3db5 Mon Sep 17 00:00:00 2001 From: Yuri Nikolic Date: Fri, 11 Aug 2023 19:03:52 +0200 Subject: [PATCH] Getting rid of sirupsen/logrus and log.Interface Signed-off-by: Yuri Nikolic --- CHANGELOG.md | 1 + go.mod | 2 - go.sum | 4 - httpgrpc/httpgrpc.go | 7 +- httpgrpc/server/server.go | 3 +- log/format.go | 56 -------------- log/global.go | 58 ++------------- log/gokit.go | 91 ++++------------------- log/gokit_test.go | 29 -------- log/interface.go | 28 ------- log/level.go | 63 ++-------------- log/level_test.go | 28 ------- log/logging.go | 32 -------- log/logrus.go | 63 ---------------- log/noop.go | 27 ------- log/ratelimit.go | 126 +++++++++----------------------- log/ratelimit_test.go | 117 +++++++++++------------------ middleware/grpc_logging.go | 33 ++++++--- middleware/grpc_logging_test.go | 6 +- middleware/logging.go | 47 ++++++------ middleware/logging_test.go | 36 ++++----- middleware/path_rewrite.go | 7 +- server/server.go | 40 ++++++---- server/server_test.go | 61 ++++++++-------- signals/signals.go | 15 ++-- user/logging.go | 10 +-- 26 files changed, 247 insertions(+), 743 deletions(-) delete mode 100644 log/format.go delete mode 100644 log/gokit_test.go delete mode 100644 log/interface.go delete mode 100644 log/level_test.go delete mode 100644 log/logging.go delete mode 100644 log/logrus.go delete mode 100644 log/noop.go diff --git a/CHANGELOG.md b/CHANGELOG.md index 6c7ddd0ff..353a823fd 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -51,6 +51,7 @@ * [CHANGE] gRPC client: use default connect timeout of 5s, and therefore enable default connect backoff max delay of 5s. #332 * [CHANGE] Remove `github.com/grafana/dskit/errors` in favour of Go's `errors` package. #357 * [CHANGE] Remove `grpcutil.IsGRPCContextCanceled()` in favour of `grpcutil.IsCanceled()`. #357 +* [CHANGE] Remove `logrus` and `log.Interface`. Replace config flags `-server.log-format.log.format` and `-server.log-level.log.level` with `-server.log.format` and `-server.log.level`. #359 * [FEATURE] Cache: Add support for configuring a Redis cache backend. #268 #271 #276 * [FEATURE] Add support for waiting on the rate limiter using the new `WaitN` method. #279 * [FEATURE] Add `log.BufferedLogger` type. #338 diff --git a/go.mod b/go.mod index bbc94ff4f..85f9693d6 100644 --- a/go.mod +++ b/go.mod @@ -37,12 +37,10 @@ require ( github.com/prometheus/common v0.44.0 github.com/prometheus/exporter-toolkit v0.10.1-0.20230714054209-2f4150c63f97 github.com/sercand/kuberesolver/v4 v4.0.0 - github.com/sirupsen/logrus v1.8.1 github.com/soheilhy/cmux v0.1.5 github.com/stretchr/testify v1.8.1 github.com/uber/jaeger-client-go v2.28.0+incompatible github.com/uber/jaeger-lib v2.2.0+incompatible - github.com/weaveworks/promrus v1.2.0 go.etcd.io/etcd/api/v3 v3.5.0 go.etcd.io/etcd/client/pkg/v3 v3.5.0 go.etcd.io/etcd/client/v3 v3.5.0 diff --git a/go.sum b/go.sum index bc6d33e6c..6b9fba7df 100644 --- a/go.sum +++ b/go.sum @@ -791,8 +791,6 @@ github.com/sercand/kuberesolver/v4 v4.0.0/go.mod h1:F4RGyuRmMAjeXHKL+w4P7AwUnPce github.com/sirupsen/logrus v1.2.0/go.mod h1:LxeOpSwHxABJmUn/MG1IvRgCAasNZTLOkJPxbbu5VWo= github.com/sirupsen/logrus v1.4.2/go.mod h1:tLMulIdttU9McNUspp0xgXVQah82FyeX6MwdIuYE2rE= github.com/sirupsen/logrus v1.6.0/go.mod h1:7uNnSEd1DgxDLC74fIahvMZmmYsHGZGEOFrfsX/uA88= -github.com/sirupsen/logrus v1.8.1 h1:dJKuHgqk1NNQlqoA6BTlM1Wf9DOH3NBjQyu0h9+AZZE= -github.com/sirupsen/logrus v1.8.1/go.mod h1:yWOB1SBYBC5VeMP7gHvWumXLIWorT60ONWic61uBYv0= github.com/soheilhy/cmux v0.1.5 h1:jjzc5WVemNEDTLwv9tlmemhC73tI08BNOIGwBOo10Js= github.com/soheilhy/cmux v0.1.5/go.mod h1:T7TcVDs9LWfQgPlPsdngu6I6QIoyIFZDDC6sNE1GqG0= github.com/spaolacci/murmur3 v0.0.0-20180118202830-f09979ecbc72/go.mod h1:JwIasOWyU6f++ZhiEuf87xNszmSA2myDM2Kzu9HwQUA= @@ -821,8 +819,6 @@ github.com/uber/jaeger-client-go v2.28.0+incompatible h1:G4QSBfvPKvg5ZM2j9MrJFdf github.com/uber/jaeger-client-go v2.28.0+incompatible/go.mod h1:WVhlPFC8FDjOFMMWRy2pZqQJSXxYSwNYOkTr/Z6d3Kk= github.com/uber/jaeger-lib v2.2.0+incompatible h1:MxZXOiR2JuoANZ3J6DE/U0kSFv/eJ/GfSYVCjK7dyaw= github.com/uber/jaeger-lib v2.2.0+incompatible/go.mod h1:ComeNDZlWwrWnDv8aPp0Ba6+uUTzImX/AauajbLI56U= -github.com/weaveworks/promrus v1.2.0 h1:jOLf6pe6/vss4qGHjXmGz4oDJQA+AOCqEL3FvvZGz7M= -github.com/weaveworks/promrus v1.2.0/go.mod h1:SaE82+OJ91yqjrE1rsvBWVzNZKcHYFtMUyS1+Ogs/KA= github.com/yuin/goldmark v1.1.25/go.mod h1:3hX8gzYuyVAZsxl0MRgGTJEmQBFcNTphYh9decYSb74= github.com/yuin/goldmark v1.1.27/go.mod h1:3hX8gzYuyVAZsxl0MRgGTJEmQBFcNTphYh9decYSb74= github.com/yuin/goldmark v1.1.32/go.mod h1:3hX8gzYuyVAZsxl0MRgGTJEmQBFcNTphYh9decYSb74= diff --git a/httpgrpc/httpgrpc.go b/httpgrpc/httpgrpc.go index 050492dfc..0d6488779 100644 --- a/httpgrpc/httpgrpc.go +++ b/httpgrpc/httpgrpc.go @@ -7,10 +7,13 @@ package httpgrpc import ( "fmt" + "github.com/go-kit/log/level" + spb "github.com/gogo/googleapis/google/rpc" "github.com/gogo/protobuf/types" "github.com/gogo/status" - log "github.com/sirupsen/logrus" + + "github.com/grafana/dskit/log" ) // Errorf returns a HTTP gRPC error than is correctly forwarded over @@ -51,7 +54,7 @@ func HTTPResponseFromError(err error) (*HTTPResponse, bool) { var resp HTTPResponse if err := types.UnmarshalAny(status.Details[0], &resp); err != nil { - log.Errorf("Got error containing non-response: %v", err) + level.Error(log.Global()).Log("msg", "got error containing non-response", "err", err) return nil, false } diff --git a/httpgrpc/server/server.go b/httpgrpc/server/server.go index 4aa48e4f2..0fab46a8a 100644 --- a/httpgrpc/server/server.go +++ b/httpgrpc/server/server.go @@ -15,6 +15,7 @@ import ( "net/url" "strings" + "github.com/go-kit/log/level" otgrpc "github.com/opentracing-contrib/go-grpc" "github.com/opentracing/opentracing-go" "github.com/sercand/kuberesolver/v4" @@ -189,7 +190,7 @@ func (c *Client) ServeHTTP(w http.ResponseWriter, r *http.Request) { if tracer := opentracing.GlobalTracer(); tracer != nil { if span := opentracing.SpanFromContext(r.Context()); span != nil { if err := tracer.Inject(span.Context(), opentracing.HTTPHeaders, opentracing.HTTPHeadersCarrier(r.Header)); err != nil { - log.Global().Warnf("Failed to inject tracing headers into request: %v", err) + level.Warn(log.Global()).Log("msg", "failed to inject tracing headers into request", "err", err) } } } diff --git a/log/format.go b/log/format.go deleted file mode 100644 index 3925b3c14..000000000 --- a/log/format.go +++ /dev/null @@ -1,56 +0,0 @@ -// Provenance-includes-location: https://github.com/weaveworks/common/blob/main/logging/format.go -// Provenance-includes-license: Apache-2.0 -// Provenance-includes-copyright: Weaveworks Ltd. - -package log - -import ( - "flag" - - "github.com/pkg/errors" - "github.com/sirupsen/logrus" -) - -// Format is a settable identifier for the output format of logs -type Format struct { - s string - Logrus logrus.Formatter -} - -// RegisterFlags adds the log format flag to the provided flagset. -func (f *Format) RegisterFlags(fs *flag.FlagSet) { - _ = f.Set("logfmt") - fs.Var(f, "log.format", "Output log messages in the given format. Valid formats: [logfmt, json]") -} - -func (f Format) String() string { - return f.s -} - -// UnmarshalYAML implements yaml.Unmarshaler. -func (f *Format) UnmarshalYAML(unmarshal func(interface{}) error) error { - var format string - if err := unmarshal(&format); err != nil { - return err - } - return f.Set(format) -} - -// MarshalYAML implements yaml.Marshaler. -func (f Format) MarshalYAML() (interface{}, error) { - return f.String(), nil -} - -// Set updates the value of the output format. Implements flag.Value -func (f *Format) Set(s string) error { - switch s { - case "logfmt": - f.Logrus = &logrus.JSONFormatter{} - case "json": - f.Logrus = &logrus.JSONFormatter{} - default: - return errors.Errorf("unrecognized log format %q", s) - } - f.s = s - return nil -} diff --git a/log/global.go b/log/global.go index 68131a156..ca6a9f00b 100644 --- a/log/global.go +++ b/log/global.go @@ -4,59 +4,13 @@ package log -var global = Noop() +import ( + "github.com/go-kit/log" +) + +var global = log.NewNopLogger() // Global returns the global logger. -func Global() Interface { +func Global() log.Logger { return global } - -// SetGlobal sets the global logger. -func SetGlobal(i Interface) { - global = i -} - -// Debugf convenience function calls the global loggerr. -func Debugf(format string, args ...interface{}) { - global.Debugf(format, args...) -} - -// Debugln convenience function calls the global logger. -func Debugln(args ...interface{}) { - global.Debugln(args...) -} - -// Infof convenience function calls the global logger. -func Infof(format string, args ...interface{}) { - global.Infof(format, args...) -} - -// Infoln convenience function calls the global logger. -func Infoln(args ...interface{}) { - global.Infoln(args...) -} - -// Warnf convenience function calls the global logger. -func Warnf(format string, args ...interface{}) { - global.Warnf(format, args...) -} - -// Warnln convenience function calls the global logger. -func Warnln(args ...interface{}) { - global.Warnln(args...) -} - -// Errorf convenience function calls the global logger. -func Errorf(format string, args ...interface{}) { - global.Errorf(format, args...) -} - -// Errorln convenience function calls the global logger. -func Errorln(args ...interface{}) { - global.Errorln(args...) -} - -// WithField convenience function calls the global logger. -func WithField(key string, value interface{}) Interface { - return global.WithField(key, value) -} diff --git a/log/gokit.go b/log/gokit.go index c956c6775..eef1f0003 100644 --- a/log/gokit.go +++ b/log/gokit.go @@ -5,18 +5,17 @@ package log import ( - "fmt" + "io" "os" "github.com/go-kit/log" "github.com/go-kit/log/level" ) -// NewGoKitFormat creates a new Interface backed by a GoKit logger -// format can be "json" or defaults to logfmt -func NewGoKitFormat(l Level, f Format) Interface { +// 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 - if f.s == "json" { + if format == "json" { logger = log.NewJSONLogger(log.NewSyncWriter(os.Stderr)) } else { logger = log.NewLogfmtLogger(log.NewSyncWriter(os.Stderr)) @@ -25,82 +24,18 @@ func NewGoKitFormat(l Level, f Format) Interface { } // stand-alone for test purposes -func addStandardFields(logger log.Logger, l Level) Interface { +func addStandardFields(logger log.Logger, l Level) log.Logger { logger = log.With(logger, "ts", log.DefaultTimestampUTC, "caller", log.Caller(5)) - logger = level.NewFilter(logger, l.Gokit) - return gokit{logger} + return level.NewFilter(logger, l.Option) } -// NewGoKit creates a new Interface backed by a GoKit logger -func NewGoKit(l Level) Interface { - return NewGoKitFormat(l, Format{s: "logfmt"}) +// NewGoKit creates a new GoKit logger with the "logfmt" format. +func NewGoKit(l Level) log.Logger { + return NewGoKitFormat(l, "logfmt") } -// GoKit wraps an existing gokit Logger. -func GoKit(logger log.Logger) Interface { - return gokit{logger} -} - -type gokit struct { - log.Logger -} - -// Helper to defer sprintf until it is needed. -type sprintf struct { - format string - args []interface{} -} - -func (s *sprintf) String() string { - return fmt.Sprintf(s.format, s.args...) -} - -// Helper to defer sprint until it is needed. -// Note we don't use Sprintln because the output is passed to go-kit as one value among many on a line -type sprint struct { - args []interface{} -} - -func (s *sprint) String() string { - return fmt.Sprint(s.args...) -} - -func (g gokit) Debugf(format string, args ...interface{}) { - level.Debug(g.Logger).Log("msg", &sprintf{format: format, args: args}) -} -func (g gokit) Debugln(args ...interface{}) { - level.Debug(g.Logger).Log("msg", &sprint{args: args}) -} - -func (g gokit) Infof(format string, args ...interface{}) { - level.Info(g.Logger).Log("msg", &sprintf{format: format, args: args}) -} -func (g gokit) Infoln(args ...interface{}) { - level.Info(g.Logger).Log("msg", &sprint{args: args}) -} - -func (g gokit) Warnf(format string, args ...interface{}) { - level.Warn(g.Logger).Log("msg", &sprintf{format: format, args: args}) -} -func (g gokit) Warnln(args ...interface{}) { - level.Warn(g.Logger).Log("msg", &sprint{args: args}) -} - -func (g gokit) Errorf(format string, args ...interface{}) { - level.Error(g.Logger).Log("msg", &sprintf{format: format, args: args}) -} -func (g gokit) Errorln(args ...interface{}) { - level.Error(g.Logger).Log("msg", &sprint{args: args}) -} - -func (g gokit) WithField(key string, value interface{}) Interface { - return gokit{log.With(g.Logger, key, value)} -} - -func (g gokit) WithFields(fields Fields) Interface { - logger := g.Logger - for k, v := range fields { - logger = log.With(logger, k, v) - } - return gokit{logger} +// 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) } diff --git a/log/gokit_test.go b/log/gokit_test.go deleted file mode 100644 index b1ca0fbdd..000000000 --- a/log/gokit_test.go +++ /dev/null @@ -1,29 +0,0 @@ -// Provenance-includes-location: https://github.com/weaveworks/common/blob/main/logging/gokit_test.go -// Provenance-includes-license: Apache-2.0 -// Provenance-includes-copyright: Weaveworks Ltd. - -package log - -import ( - "testing" - - "github.com/go-kit/log" - "github.com/go-kit/log/level" -) - -func BenchmarkDebugf(b *testing.B) { - lvl := Level{Gokit: level.AllowInfo()} - g := log.NewNopLogger() - logger := addStandardFields(g, lvl) - // Simulate the parameters used in middleware/logging.go - var ( - method = "method" - uri = "https://example.com/foobar" - statusCode = 404 - duration = 42 - ) - b.ResetTimer() - for i := 0; i < b.N; i++ { - logger.Debugf("%s %s (%d) %s", method, uri, statusCode, duration) - } -} diff --git a/log/interface.go b/log/interface.go deleted file mode 100644 index a074fef90..000000000 --- a/log/interface.go +++ /dev/null @@ -1,28 +0,0 @@ -// Provenance-includes-location: https://github.com/weaveworks/common/blob/main/logging/interface.go -// Provenance-includes-license: Apache-2.0 -// Provenance-includes-copyright: Weaveworks Ltd. - -package log - -// Interface 'unifies' gokit logging and logrus logging, such that -// the middleware in this repo can be used in projects which use either -// loggers. -type Interface interface { - Debugf(format string, args ...interface{}) - Debugln(args ...interface{}) - - Infof(format string, args ...interface{}) - Infoln(args ...interface{}) - - Errorf(format string, args ...interface{}) - Errorln(args ...interface{}) - - Warnf(format string, args ...interface{}) - Warnln(args ...interface{}) - - WithField(key string, value interface{}) Interface - WithFields(Fields) Interface -} - -// Fields convenience type for adding multiple fields to a log statement. -type Fields map[string]interface{} diff --git a/log/level.go b/log/level.go index f2b8db55b..1154affcf 100644 --- a/log/level.go +++ b/log/level.go @@ -4,79 +4,32 @@ package log -// Copy-pasted from prometheus/common/promlog. -// Copyright 2017 The Prometheus Authors -// Licensed under the Apache License, Version 2.0 (the "License"); -// you may not use this file except in compliance with the License. -// You may obtain a copy of the License at -// -// http://www.apache.org/licenses/LICENSE-2.0 -// -// Unless required by applicable law or agreed to in writing, software -// distributed under the License is distributed on an "AS IS" BASIS, -// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. -// See the License for the specific language governing permissions and -// limitations under the License. - import ( - "flag" - "github.com/go-kit/log/level" "github.com/pkg/errors" - "github.com/sirupsen/logrus" ) -// Level is a settable identifier for the minimum level a log entry -// must be have. +// Level is a settable identifier for the minimum level a log entry must have. type Level struct { - s string - Logrus logrus.Level - Gokit level.Option -} - -// RegisterFlags adds the log level flag to the provided flagset. -func (l *Level) RegisterFlags(f *flag.FlagSet) { - _ = l.Set("info") - f.Var(l, "log.level", "Only log messages with the given severity or above. Valid levels: [debug, info, warn, error]") -} - -func (l *Level) String() string { - return l.s -} - -// UnmarshalYAML implements yaml.Unmarshaler. -func (l *Level) UnmarshalYAML(unmarshal func(interface{}) error) error { - var level string - if err := unmarshal(&level); err != nil { - return err - } - return l.Set(level) -} - -// MarshalYAML implements yaml.Marshaler. -func (l Level) MarshalYAML() (interface{}, error) { - return l.String(), nil + level string + Option level.Option } // Set updates the value of the allowed level. Implments flag.Value. func (l *Level) Set(s string) error { switch s { case "debug": - l.Logrus = logrus.DebugLevel - l.Gokit = level.AllowDebug() + l.Option = level.AllowDebug() case "info": - l.Logrus = logrus.InfoLevel - l.Gokit = level.AllowInfo() + l.Option = level.AllowInfo() case "warn": - l.Logrus = logrus.WarnLevel - l.Gokit = level.AllowWarn() + l.Option = level.AllowWarn() case "error": - l.Logrus = logrus.ErrorLevel - l.Gokit = level.AllowError() + l.Option = level.AllowError() default: return errors.Errorf("unrecognized log level %q", s) } - l.s = s + l.level = s return nil } diff --git a/log/level_test.go b/log/level_test.go deleted file mode 100644 index d3532890b..000000000 --- a/log/level_test.go +++ /dev/null @@ -1,28 +0,0 @@ -// Provenance-includes-location: https://github.com/weaveworks/common/blob/main/logging/level_test.go -// Provenance-includes-license: Apache-2.0 -// Provenance-includes-copyright: Weaveworks Ltd. - -package log - -import ( - "testing" - - "github.com/stretchr/testify/require" - "gopkg.in/yaml.v2" -) - -func TestMarshalYAML(t *testing.T) { - var l Level - err := l.Set("debug") - require.NoError(t, err) - - // Test the non-pointed to Level, as people might embed it. - y, err := yaml.Marshal(l) - require.NoError(t, err) - require.Equal(t, []byte("debug\n"), y) - - // And the pointed to Level. - y, err = yaml.Marshal(&l) - require.NoError(t, err) - require.Equal(t, []byte("debug\n"), y) -} diff --git a/log/logging.go b/log/logging.go deleted file mode 100644 index 5bb80dee2..000000000 --- a/log/logging.go +++ /dev/null @@ -1,32 +0,0 @@ -// Provenance-includes-location: https://github.com/weaveworks/common/blob/main/logging/logging.go -// Provenance-includes-license: Apache-2.0 -// Provenance-includes-copyright: Weaveworks Ltd. - -package log - -import ( - "fmt" - "os" - - "github.com/sirupsen/logrus" - - "github.com/weaveworks/promrus" -) - -// Setup configures a global logrus logger to output to stderr. -// It populates the standard logrus logger as well as the global logging instance. -func Setup(logLevel string) error { - level, err := logrus.ParseLevel(logLevel) - if err != nil { - return fmt.Errorf("error parsing log level: %v", err) - } - hook, err := promrus.NewPrometheusHook() // Expose number of log messages as Prometheus metrics. - if err != nil { - return err - } - logrus.SetOutput(os.Stderr) - logrus.SetLevel(level) - logrus.AddHook(hook) - SetGlobal(Logrus(logrus.StandardLogger())) - return nil -} diff --git a/log/logrus.go b/log/logrus.go deleted file mode 100644 index df0e1ae07..000000000 --- a/log/logrus.go +++ /dev/null @@ -1,63 +0,0 @@ -// Provenance-includes-location: https://github.com/weaveworks/common/blob/main/logging/logrus.go -// Provenance-includes-license: Apache-2.0 -// Provenance-includes-copyright: Weaveworks Ltd. - -package log - -import ( - "os" - - "github.com/sirupsen/logrus" -) - -// NewLogrusFormat makes a new Interface backed by a logrus logger -// format can be "json" or defaults to logfmt -func NewLogrusFormat(level Level, f Format) Interface { - log := logrus.New() - log.Out = os.Stderr - log.Level = level.Logrus - log.Formatter = f.Logrus - return logrusLogger{log} -} - -// NewLogrus makes a new Interface backed by a logrus logger -func NewLogrus(level Level) Interface { - return NewLogrusFormat(level, Format{Logrus: &logrus.TextFormatter{}}) -} - -// Logrus wraps an existing Logrus logger. -func Logrus(l *logrus.Logger) Interface { - return logrusLogger{l} -} - -type logrusLogger struct { - *logrus.Logger -} - -func (l logrusLogger) WithField(key string, value interface{}) Interface { - return logrusEntry{ - Entry: l.Logger.WithField(key, value), - } -} - -func (l logrusLogger) WithFields(fields Fields) Interface { - return logrusEntry{ - Entry: l.Logger.WithFields(map[string]interface{}(fields)), - } -} - -type logrusEntry struct { - *logrus.Entry -} - -func (l logrusEntry) WithField(key string, value interface{}) Interface { - return logrusEntry{ - Entry: l.Entry.WithField(key, value), - } -} - -func (l logrusEntry) WithFields(fields Fields) Interface { - return logrusEntry{ - Entry: l.Entry.WithFields(map[string]interface{}(fields)), - } -} diff --git a/log/noop.go b/log/noop.go deleted file mode 100644 index 89d437468..000000000 --- a/log/noop.go +++ /dev/null @@ -1,27 +0,0 @@ -// Provenance-includes-location: https://github.com/weaveworks/common/blob/main/logging/noop.go -// Provenance-includes-license: Apache-2.0 -// Provenance-includes-copyright: Weaveworks Ltd. - -package log - -// Noop logger. -func Noop() Interface { - return noop{} -} - -type noop struct{} - -func (noop) Debugf(string, ...interface{}) {} -func (noop) Debugln(...interface{}) {} -func (noop) Infof(string, ...interface{}) {} -func (noop) Infoln(...interface{}) {} -func (noop) Warnf(string, ...interface{}) {} -func (noop) Warnln(...interface{}) {} -func (noop) Errorf(string, ...interface{}) {} -func (noop) Errorln(...interface{}) {} -func (noop) WithField(string, interface{}) Interface { - return noop{} -} -func (noop) WithFields(Fields) Interface { - return noop{} -} diff --git a/log/ratelimit.go b/log/ratelimit.go index 9fc592f4a..b384797c8 100644 --- a/log/ratelimit.go +++ b/log/ratelimit.go @@ -1,20 +1,15 @@ package log import ( + "github.com/go-kit/log" + "github.com/go-kit/log/level" "github.com/prometheus/client_golang/prometheus" "github.com/prometheus/client_golang/prometheus/promauto" "golang.org/x/time/rate" ) -const ( - infoLevel = "info" - debugLevel = "debug" - warnLevel = "warning" - errorLevel = "error" -) - type RateLimitedLogger struct { - next Interface + next log.Logger limiter *rate.Limiter discardedInfoLogLinesCounter prometheus.Counter @@ -23,9 +18,9 @@ type RateLimitedLogger struct { discardedErrorLogLinesCounter prometheus.Counter } -// NewRateLimitedLogger returns a logger.Interface that is limited to the given number of logs per second, +// NewRateLimitedLogger returns a log.Logger that is limited to the given number of logs per second, // with the given burst size. -func NewRateLimitedLogger(logger Interface, logsPerSecond rate.Limit, burstSize int, reg prometheus.Registerer) Interface { +func NewRateLimitedLogger(logger log.Logger, logsPerSecond rate.Limit, burstSize int, reg prometheus.Registerer) log.Logger { discardedLogLinesCounter := promauto.With(reg).NewCounterVec(prometheus.CounterOpts{ Name: "logger_rate_limit_discarded_log_lines_total", Help: "Total number of discarded log lines per level.", @@ -34,95 +29,42 @@ func NewRateLimitedLogger(logger Interface, logsPerSecond rate.Limit, burstSize return &RateLimitedLogger{ next: logger, limiter: rate.NewLimiter(logsPerSecond, burstSize), - discardedInfoLogLinesCounter: discardedLogLinesCounter.WithLabelValues(infoLevel), - discardedDebugLogLinesCounter: discardedLogLinesCounter.WithLabelValues(debugLevel), - discardedWarnLogLinesCounter: discardedLogLinesCounter.WithLabelValues(warnLevel), - discardedErrorLogLinesCounter: discardedLogLinesCounter.WithLabelValues(errorLevel), - } -} - -func (l *RateLimitedLogger) Debugf(format string, args ...interface{}) { - if l.limiter.Allow() { - l.next.Debugf(format, args...) - } else { - l.discardedDebugLogLinesCounter.Inc() - } -} - -func (l *RateLimitedLogger) Debugln(args ...interface{}) { - if l.limiter.Allow() { - l.next.Debugln(args...) - } else { - l.discardedDebugLogLinesCounter.Inc() - } -} - -func (l *RateLimitedLogger) Infof(format string, args ...interface{}) { - if l.limiter.Allow() { - l.next.Infof(format, args...) - } else { - l.discardedInfoLogLinesCounter.Inc() - } -} - -func (l *RateLimitedLogger) Infoln(args ...interface{}) { - if l.limiter.Allow() { - l.next.Infoln(args...) - } else { - l.discardedInfoLogLinesCounter.Inc() + discardedInfoLogLinesCounter: discardedLogLinesCounter.WithLabelValues(level.InfoValue().String()), + discardedDebugLogLinesCounter: discardedLogLinesCounter.WithLabelValues(level.DebugValue().String()), + discardedWarnLogLinesCounter: discardedLogLinesCounter.WithLabelValues(level.WarnValue().String()), + discardedErrorLogLinesCounter: discardedLogLinesCounter.WithLabelValues(level.ErrorValue().String()), } } -func (l *RateLimitedLogger) Errorf(format string, args ...interface{}) { +func (l *RateLimitedLogger) Log(keyvals ...interface{}) error { if l.limiter.Allow() { - l.next.Errorf(format, args...) - } else { - l.discardedErrorLogLinesCounter.Inc() + return l.next.Log(keyvals...) } -} - -func (l *RateLimitedLogger) Errorln(args ...interface{}) { - if l.limiter.Allow() { - l.next.Errorln(args...) - } else { - l.discardedErrorLogLinesCounter.Inc() + counter := l.getCounterFromKeyvals(keyvals...) + if counter != nil { + counter.Inc() } + return nil } -func (l *RateLimitedLogger) Warnf(format string, args ...interface{}) { - if l.limiter.Allow() { - l.next.Warnf(format, args...) - } else { - l.discardedWarnLogLinesCounter.Inc() - } -} - -func (l *RateLimitedLogger) Warnln(args ...interface{}) { - if l.limiter.Allow() { - l.next.Warnln(args...) - } else { - l.discardedWarnLogLinesCounter.Inc() - } -} - -func (l *RateLimitedLogger) WithField(key string, value interface{}) Interface { - return &RateLimitedLogger{ - next: l.next.WithField(key, value), - limiter: l.limiter, - discardedInfoLogLinesCounter: l.discardedInfoLogLinesCounter, - discardedDebugLogLinesCounter: l.discardedDebugLogLinesCounter, - discardedWarnLogLinesCounter: l.discardedWarnLogLinesCounter, - discardedErrorLogLinesCounter: l.discardedErrorLogLinesCounter, - } -} - -func (l *RateLimitedLogger) WithFields(f Fields) Interface { - return &RateLimitedLogger{ - next: l.next.WithFields(f), - limiter: l.limiter, - discardedInfoLogLinesCounter: l.discardedInfoLogLinesCounter, - discardedDebugLogLinesCounter: l.discardedDebugLogLinesCounter, - discardedWarnLogLinesCounter: l.discardedWarnLogLinesCounter, - discardedErrorLogLinesCounter: l.discardedErrorLogLinesCounter, +func (l *RateLimitedLogger) getCounterFromKeyvals(keyvals ...interface{}) prometheus.Counter { + for i := 0; i < len(keyvals); i += 2 { + levelKey, ok := keyvals[i].(string) + if ok && levelKey == "level" && i+1 < len(keyvals) { + levelValue := keyvals[i+1] + switch levelValue { + case level.InfoValue(): + return l.discardedInfoLogLinesCounter + case level.DebugValue(): + return l.discardedDebugLogLinesCounter + case level.WarnValue(): + return l.discardedWarnLogLinesCounter + case level.ErrorValue(): + return l.discardedErrorLogLinesCounter + default: + return nil + } + } } + return nil } diff --git a/log/ratelimit_test.go b/log/ratelimit_test.go index fa0282a0d..08febb9d9 100644 --- a/log/ratelimit_test.go +++ b/log/ratelimit_test.go @@ -6,9 +6,10 @@ import ( "testing" "time" + "github.com/go-kit/log" + "github.com/go-kit/log/level" "github.com/prometheus/client_golang/prometheus" "github.com/prometheus/client_golang/prometheus/testutil" - "github.com/sirupsen/logrus" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" ) @@ -19,11 +20,20 @@ func TestRateLimitedLoggerLogs(t *testing.T) { reg := prometheus.NewPedanticRegistry() r := NewRateLimitedLogger(c, 1, 1, reg) - r.Errorln("Error will be logged") + level.Error(r).Log("msg", "error will be logged") assert.Equal(t, 1, c.count) - logContains := []string{"error", "Error will be logged"} + logContains := []string{"error", "error will be logged"} c.assertContains(t, logContains) + + require.NoError(t, testutil.GatherAndCompare(reg, strings.NewReader(` + # HELP logger_rate_limit_discarded_log_lines_total Total number of discarded log lines per level. + # TYPE logger_rate_limit_discarded_log_lines_total counter + logger_rate_limit_discarded_log_lines_total{level="info"} 0 + logger_rate_limit_discarded_log_lines_total{level="debug"} 0 + logger_rate_limit_discarded_log_lines_total{level="warn"} 0 + logger_rate_limit_discarded_log_lines_total{level="error"} 0 + `))) } func TestRateLimitedLoggerLimits(t *testing.T) { @@ -32,19 +42,19 @@ func TestRateLimitedLoggerLimits(t *testing.T) { reg := prometheus.NewPedanticRegistry() r := NewRateLimitedLogger(c, 2, 2, reg) - r.Errorln("error 1 will be logged") + level.Error(r).Log("msg", "error 1 will be logged") assert.Equal(t, 1, c.count) c.assertContains(t, []string{"error", "error 1 will be logged"}) - r.Infoln("info 1 will be logged") + level.Info(r).Log("msg", "info 1 will be logged") assert.Equal(t, 2, c.count) c.assertContains(t, []string{"info", "info 1 will be logged"}) - r.Debugln("debug 1 will be discarded") + level.Debug(r).Log("msg", "debug 1 will be discarded") assert.Equal(t, 2, c.count) c.assertNotContains(t, "debug 1 will be discarded") - r.Warnln("warning 1 will be discarded") + level.Warn(r).Log("msg", "warning 1 will be discarded") assert.Equal(t, 2, c.count) c.assertNotContains(t, "warning 1 will be discarded") @@ -53,25 +63,25 @@ func TestRateLimitedLoggerLimits(t *testing.T) { # TYPE logger_rate_limit_discarded_log_lines_total counter logger_rate_limit_discarded_log_lines_total{level="info"} 0 logger_rate_limit_discarded_log_lines_total{level="debug"} 1 - logger_rate_limit_discarded_log_lines_total{level="warning"} 1 + logger_rate_limit_discarded_log_lines_total{level="warn"} 1 logger_rate_limit_discarded_log_lines_total{level="error"} 0 `))) // we wait 1 second, so the next group of lines can be logged time.Sleep(time.Second) - r.Debugln("debug 2 will be logged") + level.Debug(r).Log("msg", "debug 2 will be logged") assert.Equal(t, 3, c.count) c.assertContains(t, []string{"debug", "debug 2 will be logged"}) - r.Infoln("info 2 will be logged") + level.Info(r).Log("msg", "info 2 will be logged") assert.Equal(t, 4, c.count) c.assertContains(t, []string{"info", "info 2 will be logged"}) - r.Errorln("error 2 will be discarded") + level.Error(r).Log("msg", "error 2 will be discarded") assert.Equal(t, 4, c.count) c.assertNotContains(t, "error 2 will be discarded") - r.Warnln("warning 2 will be discarded") + level.Warn(r).Log("msg", "warning 2 will be discarded") assert.Equal(t, 4, c.count) c.assertNotContains(t, "warning 2 will be discarded") @@ -81,7 +91,7 @@ func TestRateLimitedLoggerLimits(t *testing.T) { logger_rate_limit_discarded_log_lines_total{level="info"} 0 logger_rate_limit_discarded_log_lines_total{level="debug"} 1 logger_rate_limit_discarded_log_lines_total{level="error"} 1 - logger_rate_limit_discarded_log_lines_total{level="warning"} 2 + logger_rate_limit_discarded_log_lines_total{level="warn"} 2 `))) } @@ -90,20 +100,20 @@ func TestRateLimitedLoggerWithFields(t *testing.T) { c := newCounterLogger(buf) reg := prometheus.NewPedanticRegistry() logger := NewRateLimitedLogger(c, 0.0001, 1, reg) - loggerWithFields := logger.WithField("key", "value") + loggerWithFields := log.With(logger, "key", "value") - loggerWithFields.Errorln("Error will be logged") + level.Error(loggerWithFields).Log("msg", "error will be logged") assert.Equal(t, 1, c.count) - c.assertContains(t, []string{"key", "value", "error", "Error will be logged"}) + c.assertContains(t, []string{"key", "value", "error", "error will be logged"}) - logger.Infoln("Info will not be logged") - c.assertNotContains(t, "Info will not be logged") + level.Info(logger).Log("msg", "info will not be logged") + c.assertNotContains(t, "info will not be logged") - loggerWithFields.Debugln("Debug will not be logged") - c.assertNotContains(t, "Debug will not be logged") + level.Debug(loggerWithFields).Log("msg", "debug will not be logged") + c.assertNotContains(t, "debug will not be logged") - loggerWithFields.Warnln("Warning will not be logged") - c.assertNotContains(t, "Warning will not be logged") + level.Warn(loggerWithFields).Log("msg", "warning will not be logged") + c.assertNotContains(t, "warning will not be logged") assert.Equal(t, 1, c.count) require.NoError(t, testutil.GatherAndCompare(reg, strings.NewReader(` @@ -111,65 +121,23 @@ func TestRateLimitedLoggerWithFields(t *testing.T) { # TYPE logger_rate_limit_discarded_log_lines_total counter logger_rate_limit_discarded_log_lines_total{level="info"} 1 logger_rate_limit_discarded_log_lines_total{level="debug"} 1 - logger_rate_limit_discarded_log_lines_total{level="warning"} 1 + logger_rate_limit_discarded_log_lines_total{level="warn"} 1 logger_rate_limit_discarded_log_lines_total{level="error"} 0 `))) } type counterLogger struct { - logger Interface + logger log.Logger buf *bytes.Buffer count int } -func (c *counterLogger) Debugf(format string, args ...interface{}) { - c.logger.Debugf(format, args...) - c.count++ -} - -func (c *counterLogger) Debugln(args ...interface{}) { - c.logger.Debugln(args...) - c.count++ -} - -func (c *counterLogger) Infof(format string, args ...interface{}) { - c.logger.Infof(format, args...) - c.count++ -} - -func (c *counterLogger) Infoln(args ...interface{}) { - c.logger.Infoln(args...) - c.count++ -} - -func (c *counterLogger) Warnf(format string, args ...interface{}) { - c.logger.Warnf(format, args...) - c.count++ -} - -func (c *counterLogger) Warnln(args ...interface{}) { - c.logger.Warnln(args...) - c.count++ -} - -func (c *counterLogger) Errorf(format string, args ...interface{}) { - c.logger.Errorf(format, args...) - c.count++ -} - -func (c *counterLogger) Errorln(args ...interface{}) { - c.logger.Errorln(args...) - c.count++ -} - -func (c *counterLogger) WithField(key string, value interface{}) Interface { - c.logger = c.logger.WithField(key, value) - return c -} - -func (c *counterLogger) WithFields(fields Fields) Interface { - c.logger = c.logger.WithFields(fields) - return c +func (c *counterLogger) Log(keyvals ...interface{}) error { + err := c.logger.Log(keyvals...) + if err == nil { + c.count++ + } + return err } func (c *counterLogger) assertContains(t *testing.T, logContains []string) { @@ -183,11 +151,8 @@ func (c *counterLogger) assertNotContains(t *testing.T, content string) { } func newCounterLogger(buf *bytes.Buffer) *counterLogger { - logrusLogger := logrus.New() - logrusLogger.Out = buf - logrusLogger.Level = logrus.DebugLevel return &counterLogger{ - logger: Logrus(logrusLogger), + logger: log.NewLogfmtLogger(buf), buf: buf, } } diff --git a/middleware/grpc_logging.go b/middleware/grpc_logging.go index bb9c99571..b4ee986e1 100644 --- a/middleware/grpc_logging.go +++ b/middleware/grpc_logging.go @@ -7,12 +7,14 @@ package middleware import ( "context" "errors" + "fmt" "time" + gokit_log "github.com/go-kit/log" + "github.com/go-kit/log/level" "google.golang.org/grpc" grpcUtils "github.com/grafana/dskit/grpcutil" - "github.com/grafana/dskit/log" "github.com/grafana/dskit/user" ) @@ -28,7 +30,7 @@ type OptionalLogging interface { // GRPCServerLog logs grpc requests, errors, and latency. type GRPCServerLog struct { - Log log.Interface + Log gokit_log.Logger // WithRequest will log the entire request rather than just the error WithRequest bool DisableRequestSuccessLog bool @@ -46,18 +48,22 @@ func (s GRPCServerLog) UnaryServerInterceptor(ctx context.Context, req interface return resp, err } - entry := user.LogWith(ctx, s.Log).WithFields(log.Fields{"method": info.FullMethod, "duration": time.Since(begin)}) + logger := user.LogWith(ctx, s.Log) + logger = gokit_log.With(logger, "method", info.FullMethod) + logger = gokit_log.With(logger, "duration", time.Since(begin)) if err != nil { if s.WithRequest { - entry = entry.WithField("request", req) + logger = gokit_log.With(logger, "request", req) } if grpcUtils.IsCanceled(err) { - entry.WithField(errorKey, err).Debugln(gRPC) + logger = gokit_log.With(logger, errorKey, err) + level.Debug(logger).Log("msg", gRPC) } else { - entry.WithField(errorKey, err).Warnln(gRPC) + logger = gokit_log.With(logger, errorKey, err) + level.Warn(logger).Log("msg", gRPC) } } else { - entry.Debugf("%s (success)", gRPC) + level.Debug(logger).Log("msg", fmt.Sprintf("%s (success)", gRPC)) } return resp, err } @@ -70,15 +76,20 @@ func (s GRPCServerLog) StreamServerInterceptor(srv interface{}, ss grpc.ServerSt return nil } - entry := user.LogWith(ss.Context(), s.Log).WithFields(log.Fields{"method": info.FullMethod, "duration": time.Since(begin)}) + logger := user.LogWith(ss.Context(), s.Log) + logger = gokit_log.With(logger, "method", info.FullMethod) + logger = gokit_log.With(logger, "duration", time.Since(begin)) + if err != nil { if grpcUtils.IsCanceled(err) { - entry.WithField(errorKey, err).Debugln(gRPC) + logger = gokit_log.With(logger, errorKey, err) + level.Debug(logger).Log("msg", gRPC) } else { - entry.WithField(errorKey, err).Warnln(gRPC) + logger = gokit_log.With(logger, errorKey, err) + level.Warn(logger).Log("msg", gRPC) } } else { - entry.Debugf("%s (success)", gRPC) + level.Debug(logger).Log("msg", fmt.Sprintf("%s (success)", gRPC)) } return err } diff --git a/middleware/grpc_logging_test.go b/middleware/grpc_logging_test.go index 16be43fe7..81f9af9c7 100644 --- a/middleware/grpc_logging_test.go +++ b/middleware/grpc_logging_test.go @@ -15,12 +15,10 @@ import ( "github.com/go-kit/log/level" "github.com/stretchr/testify/require" "google.golang.org/grpc" - - dskit_log "github.com/grafana/dskit/log" ) func BenchmarkGRPCServerLog_UnaryServerInterceptor_NoError(b *testing.B) { - logger := dskit_log.GoKit(level.NewFilter(log.NewNopLogger(), level.AllowError())) + logger := level.NewFilter(log.NewNopLogger(), level.AllowError()) l := GRPCServerLog{Log: logger, WithRequest: false, DisableRequestSuccessLog: true} ctx := context.Background() info := &grpc.UnaryServerInfo{FullMethod: "Test"} @@ -64,7 +62,7 @@ func TestGrpcLogging(t *testing.T) { }} { t.Run("", func(t *testing.T) { buf := bytes.NewBuffer(nil) - logger := dskit_log.GoKit(log.NewLogfmtLogger(buf)) + logger := log.NewLogfmtLogger(buf) l := GRPCServerLog{Log: logger, WithRequest: true, DisableRequestSuccessLog: false} handler := func(ctx context.Context, req interface{}) (interface{}, error) { diff --git a/middleware/logging.go b/middleware/logging.go index ca13f330e..bd2bad974 100644 --- a/middleware/logging.go +++ b/middleware/logging.go @@ -8,17 +8,21 @@ import ( "bytes" "context" "errors" + "fmt" "net/http" "time" - "github.com/grafana/dskit/log" + "github.com/go-kit/log" + "github.com/go-kit/log/level" + + dskit_log "github.com/grafana/dskit/log" "github.com/grafana/dskit/tracing" "github.com/grafana/dskit/user" ) // Log middleware logs http requests type Log struct { - Log log.Interface + Log log.Logger DisableRequestSuccessLog bool LogRequestHeaders bool // LogRequestHeaders true -> dump http headers at debug log level LogRequestAtInfoLevel bool // LogRequestAtInfoLevel true -> log requests at info log level @@ -32,7 +36,7 @@ var defaultExcludedHeaders = map[string]bool{ "Authorization": true, } -func NewLogMiddleware(log log.Interface, logRequestHeaders bool, logRequestAtInfoLevel bool, sourceIPs *SourceIPExtractor, headersList []string) Log { +func NewLogMiddleware(log log.Logger, logRequestHeaders bool, logRequestAtInfoLevel bool, sourceIPs *SourceIPExtractor, headersList []string) Log { httpHeadersToExclude := map[string]bool{} for header := range defaultExcludedHeaders { httpHeadersToExclude[header] = true @@ -51,17 +55,17 @@ func NewLogMiddleware(log log.Interface, logRequestHeaders bool, logRequestAtInf } // logWithRequest information from the request and context as fields. -func (l Log) logWithRequest(r *http.Request) log.Interface { +func (l Log) logWithRequest(r *http.Request) log.Logger { localLog := l.Log traceID, ok := tracing.ExtractTraceID(r.Context()) if ok { - localLog = localLog.WithField("traceID", traceID) + localLog = log.With(localLog, "traceID", traceID) } if l.SourceIPs != nil { ips := l.SourceIPs.Get(r) if ips != "" { - localLog = localLog.WithField("sourceIPs", ips) + localLog = log.With(localLog, "sourceIPs", ips) } } @@ -78,7 +82,7 @@ func (l Log) Wrap(next http.Handler) http.Handler { headers, err := dumpRequest(r, l.HTTPHeadersToExclude) if err != nil { headers = nil - requestLog.Errorf("Could not dump request headers: %v", err) + level.Error(requestLog).Log("msg", fmt.Sprintf("could not dump request headers: %v", err)) } var buf bytes.Buffer wrapped := newBadResponseLoggingWriter(w, &buf) @@ -89,12 +93,12 @@ func (l Log) Wrap(next http.Handler) http.Handler { if writeErr != nil { 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) + 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)) } else { - requestLog.Debugf("%s %s %s, request cancelled: %s ws: %v; %s", r.Method, uri, time.Since(begin), writeErr, IsWSHandshakeRequest(r), headers) + 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)) } } else { - requestLog.Warnf("%s %s %s, error: %s ws: %v; %s", r.Method, uri, time.Since(begin), writeErr, IsWSHandshakeRequest(r), headers) + 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)) } return @@ -107,21 +111,20 @@ func (l Log) Wrap(next http.Handler) http.Handler { case 100 <= statusCode && statusCode < 500 || statusCode == http.StatusBadGateway || statusCode == http.StatusServiceUnavailable: if l.LogRequestAtInfoLevel { - requestLog.Infof("%s %s (%d) %s", r.Method, uri, statusCode, time.Since(begin)) - if l.LogRequestHeaders && headers != nil { - requestLog.Infof("ws: %v; %s", IsWSHandshakeRequest(r), string(headers)) + 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))) + } else { + level.Info(requestLog).Log("msg", fmt.Sprintf("%s %s (%d) %s", r.Method, uri, statusCode, time.Since(begin))) + } + } 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))) + } else { + level.Debug(requestLog).Log("msg", fmt.Sprintf("%s %s (%d) %s", r.Method, uri, statusCode, time.Since(begin))) } - return - } - - requestLog.Debugf("%s %s (%d) %s", r.Method, uri, statusCode, time.Since(begin)) - if l.LogRequestHeaders && headers != nil { - requestLog.Debugf("ws: %v; %s", IsWSHandshakeRequest(r), string(headers)) } default: - requestLog.Warnf("%s %s (%d) %s Response: %q ws: %v; %s", - r.Method, uri, statusCode, time.Since(begin), buf.Bytes(), IsWSHandshakeRequest(r), headers) + 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)) } }) } @@ -129,7 +132,7 @@ func (l Log) Wrap(next http.Handler) http.Handler { // Logging middleware logs each HTTP request method, path, response code and // duration for all HTTP requests. var Logging = Log{ - Log: log.Global(), + Log: dskit_log.Global(), } func dumpRequest(req *http.Request, httpHeadersToExclude map[string]bool) ([]byte, error) { diff --git a/middleware/logging_test.go b/middleware/logging_test.go index 5a7ae602c..4352e0505 100644 --- a/middleware/logging_test.go +++ b/middleware/logging_test.go @@ -13,10 +13,9 @@ import ( "net/http/httptest" "testing" - "github.com/sirupsen/logrus" - "github.com/stretchr/testify/require" - "github.com/grafana/dskit/log" + + "github.com/stretchr/testify/require" ) func TestBadWriteLogging(t *testing.T) { @@ -28,18 +27,18 @@ func TestBadWriteLogging(t *testing.T) { logContains: []string{"debug", "request cancelled: context canceled"}, }, { err: errors.New("yolo"), - logContains: []string{"warning", "error: yolo"}, + logContains: []string{"warn", "error: yolo"}, }, { err: nil, logContains: []string{"debug", "GET http://example.com/foo (200)"}, }} { buf := bytes.NewBuffer(nil) - logrusLogger := logrus.New() - logrusLogger.Out = buf - logrusLogger.Level = logrus.DebugLevel + var level log.Level + require.NoError(t, level.Set("debug")) + logger := log.NewGoKitWriter(level, buf) loggingMiddleware := Log{ - Log: log.Logrus(logrusLogger), + Log: logger, } handler := func(w http.ResponseWriter, r *http.Request) { _, _ = io.WriteString(w, "Hello World!") @@ -77,12 +76,11 @@ func TestDisabledSuccessfulRequestsLogging(t *testing.T) { }, } { buf := bytes.NewBuffer(nil) - logrusLogger := logrus.New() - logrusLogger.Out = buf - logrusLogger.Level = logrus.DebugLevel + var level log.Level + require.NoError(t, level.Set("debug")) loggingMiddleware := Log{ - Log: log.Logrus(logrusLogger), + Log: log.NewGoKitWriter(level, buf), DisableRequestSuccessLog: tc.disableLog, } @@ -123,12 +121,11 @@ func TestLoggingRequestsAtInfoLevel(t *testing.T) { logContains: []string{"info", "GET http://example.com/foo (200)"}, }} { buf := bytes.NewBuffer(nil) - logrusLogger := logrus.New() - logrusLogger.Out = buf - logrusLogger.Level = logrus.DebugLevel + var level log.Level + require.NoError(t, level.Set("debug")) loggingMiddleware := Log{ - Log: log.Logrus(logrusLogger), + Log: log.NewGoKitWriter(level, buf), LogRequestAtInfoLevel: true, } handler := func(w http.ResponseWriter, r *http.Request) { @@ -179,11 +176,10 @@ func TestLoggingRequestWithExcludedHeaders(t *testing.T) { } { t.Run(tc.name, func(t *testing.T) { buf := bytes.NewBuffer(nil) - logrusLogger := logrus.New() - logrusLogger.Out = buf - logrusLogger.Level = logrus.DebugLevel + var level log.Level + require.NoError(t, level.Set("debug")) - loggingMiddleware := NewLogMiddleware(log.Logrus(logrusLogger), true, false, nil, tc.excludeHeaderList) + loggingMiddleware := NewLogMiddleware(log.NewGoKitWriter(level, buf), true, false, nil, tc.excludeHeaderList) handler := func(w http.ResponseWriter, r *http.Request) { _, _ = io.WriteString(w, "Hello world!") diff --git a/middleware/path_rewrite.go b/middleware/path_rewrite.go index c9e917a72..71b0b66bb 100644 --- a/middleware/path_rewrite.go +++ b/middleware/path_rewrite.go @@ -5,11 +5,14 @@ package middleware import ( + "fmt" "net/http" "net/url" "regexp" - log "github.com/sirupsen/logrus" + "github.com/go-kit/log/level" + + "github.com/grafana/dskit/log" ) // PathRewrite supports regex matching and replace on Request URIs @@ -31,7 +34,7 @@ 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 { - log.Errorf("Got invalid url-encoded path %v after applying path rewrite %v: %v", r.URL.RawPath, p, err) + level.Error(log.Global()).Log(fmt.Sprintf("got invalid url-encoded path %v after applying path rewrite %v: %v", r.URL.RawPath, p, err)) w.WriteHeader(http.StatusInternalServerError) return } diff --git a/server/server.go b/server/server.go index 140b9ec4e..17ec98dce 100644 --- a/server/server.go +++ b/server/server.go @@ -16,6 +16,8 @@ import ( "strings" "time" + gokit_log "github.com/go-kit/log" + "github.com/go-kit/log/level" "github.com/gorilla/mux" otgrpc "github.com/opentracing-contrib/go-grpc" "github.com/opentracing/opentracing-go" @@ -117,15 +119,15 @@ type Config struct { GRPCServerMinTimeBetweenPings time.Duration `yaml:"grpc_server_min_time_between_pings"` GRPCServerPingWithoutStreamAllowed bool `yaml:"grpc_server_ping_without_stream_allowed"` - LogFormat log.Format `yaml:"log_format"` - LogLevel log.Level `yaml:"log_level"` - Log log.Interface `yaml:"-"` - LogSourceIPs bool `yaml:"log_source_ips_enabled"` - LogSourceIPsHeader string `yaml:"log_source_ips_header"` - LogSourceIPsRegex string `yaml:"log_source_ips_regex"` - LogRequestHeaders bool `yaml:"log_request_headers"` - LogRequestAtInfoLevel bool `yaml:"log_request_at_info_level_enabled"` - LogRequestExcludeHeadersList string `yaml:"log_request_exclude_headers_list"` + LogFormat string `yaml:"log_format"` + LogLevel string `yaml:"log_level"` + Log gokit_log.Logger `yaml:"-"` + LogSourceIPs bool `yaml:"log_source_ips_enabled"` + LogSourceIPsHeader string `yaml:"log_source_ips_header"` + LogSourceIPsRegex string `yaml:"log_source_ips_regex"` + LogRequestHeaders bool `yaml:"log_request_headers"` + LogRequestAtInfoLevel bool `yaml:"log_request_at_info_level_enabled"` + LogRequestExcludeHeadersList string `yaml:"log_request_exclude_headers_list"` // If not set, default signal handler is used. SignalHandler SignalHandler `yaml:"-"` @@ -175,8 +177,8 @@ func (cfg *Config) RegisterFlags(f *flag.FlagSet) { f.DurationVar(&cfg.GRPCServerMinTimeBetweenPings, "server.grpc.keepalive.min-time-between-pings", 5*time.Minute, "Minimum amount of time a client should wait before sending a keepalive ping. If client sends keepalive ping more often, server will send GOAWAY and close the connection.") f.BoolVar(&cfg.GRPCServerPingWithoutStreamAllowed, "server.grpc.keepalive.ping-without-stream-allowed", false, "If true, server allows keepalive pings even when there are no active streams(RPCs). If false, and client sends ping when there are no active streams, server will send GOAWAY and close the connection.") f.StringVar(&cfg.PathPrefix, "server.path-prefix", "", "Base path to serve all API routes from (e.g. /v1/)") - cfg.LogFormat.RegisterFlags(f) - cfg.LogLevel.RegisterFlags(f) + f.StringVar(&cfg.LogFormat, "server.log-format", "logfmt", "Output log messages in the given format. Valid formats: [logfmt, json]") + f.StringVar(&cfg.LogLevel, "server.log-level", "info", "Only log messages with the given severity or above. Valid levels: [debug, info, warn, error]") f.BoolVar(&cfg.LogSourceIPs, "server.log-source-ips-enabled", false, "Optionally log the source IPs.") f.StringVar(&cfg.LogSourceIPsHeader, "server.log-source-ips-header", "", "Header field storing the source IPs. Only used if server.log-source-ips-enabled is true. If not set the default Forwarded, X-Real-IP and X-Forwarded-For headers are used") f.StringVar(&cfg.LogSourceIPsRegex, "server.log-source-ips-regex", "", "Regex for matching the source IPs. Only used if server.log-source-ips-enabled is true. If not set the default Forwarded, X-Real-IP and X-Forwarded-For headers are used") @@ -212,7 +214,7 @@ type Server struct { HTTP *mux.Router HTTPServer *http.Server GRPC *grpc.Server - Log log.Interface + Log gokit_log.Logger Registerer prometheus.Registerer Gatherer prometheus.Gatherer } @@ -230,11 +232,15 @@ func NewWithMetrics(cfg Config, metrics *Metrics) (*Server, error) { } func newServer(cfg Config, metrics *Metrics) (*Server, error) { - // If user doesn't supply a logging implementation, by default instantiate - // logrus. + // If user doesn't supply a logging implementation, by default instantiate go-kit. logger := cfg.Log if logger == nil { - logger = log.NewLogrus(cfg.LogLevel) + var level log.Level + err := level.Set(cfg.LogLevel) + if err != nil { + return nil, err + } + logger = log.NewGoKit(level) } gatherer := cfg.Gatherer @@ -331,7 +337,9 @@ func newServer(cfg Config, metrics *Metrics) (*Server, error) { } } - logger.WithField("http", httpListener.Addr()).WithField("grpc", grpcListener.Addr()).Infof("server listening on addresses") + loggerWithFields := gokit_log.With(logger, "http", httpListener.Addr()) + loggerWithFields = gokit_log.With(loggerWithFields, "grpc", grpcListener.Addr()) + level.Info(loggerWithFields).Log("msg", "server listening on addresses") // Setup gRPC server serverLog := middleware.GRPCServerLog{ diff --git a/server/server_test.go b/server/server_test.go index 7e596c869..564a1aaf6 100644 --- a/server/server_test.go +++ b/server/server_test.go @@ -19,6 +19,7 @@ import ( "testing" "time" + gokit_log "github.com/go-kit/log" "github.com/prometheus/client_golang/prometheus/testutil" "github.com/prometheus/common/config" "google.golang.org/grpc" @@ -84,6 +85,7 @@ func TestTCPv4Network(t *testing.T) { } t.Run("http", func(t *testing.T) { cfg.MetricsNamespace = "testing_http_tcp4" + cfg.LogLevel = "info" srv, err := New(cfg) require.NoError(t, err) @@ -461,6 +463,7 @@ func TestRunReturnsError(t *testing.T) { } t.Run("http", func(t *testing.T) { cfg.MetricsNamespace = "testing_http" + cfg.LogLevel = "info" srv, err := New(cfg) require.NoError(t, err) @@ -493,8 +496,6 @@ func TestRunReturnsError(t *testing.T) { // Test to see what the logging of a 500 error looks like func TestMiddlewareLogging(t *testing.T) { - var level log.Level - require.NoError(t, level.Set("info")) cfg := Config{ HTTPListenNetwork: DefaultNetwork, HTTPListenAddress: "localhost", @@ -503,7 +504,7 @@ func TestMiddlewareLogging(t *testing.T) { GRPCListenAddress: "localhost", HTTPMiddleware: []middleware.Interface{middleware.Logging}, MetricsNamespace: "testing_logging", - LogLevel: level, + LogLevel: "info", DoNotAddDefaultHTTPMiddleware: true, Router: &mux.Router{}, } @@ -553,6 +554,7 @@ func TestTLSServer(t *testing.T) { GRPCListenNetwork: DefaultNetwork, GRPCListenAddress: "localhost", GRPCListenPort: 9194, + LogLevel: "info", } server, err := New(cfg) require.NoError(t, err) @@ -612,9 +614,6 @@ func TestTLSServer(t *testing.T) { } func TestTLSServerWithInlineCerts(t *testing.T) { - var level log.Level - require.NoError(t, level.Set("info")) - cmd := exec.Command("bash", "certs/genCerts.sh", "certs", "1") err := cmd.Run() require.NoError(t, err) @@ -648,6 +647,7 @@ func TestTLSServerWithInlineCerts(t *testing.T) { GRPCListenNetwork: DefaultNetwork, GRPCListenAddress: "localhost", GRPCListenPort: 9194, + LogLevel: "info", } server, err := New(cfg) defer server.Shutdown() @@ -705,37 +705,35 @@ func TestTLSServerWithInlineCerts(t *testing.T) { } type FakeLogger struct { - sourceIPs string + logger gokit_log.Logger + buf *bytes.Buffer } -func (f *FakeLogger) Debugf(_ string, _ ...interface{}) {} -func (f *FakeLogger) Debugln(_ ...interface{}) {} - -func (f *FakeLogger) Infof(_ string, _ ...interface{}) {} -func (f *FakeLogger) Infoln(_ ...interface{}) {} - -func (f *FakeLogger) Errorf(_ string, _ ...interface{}) {} -func (f *FakeLogger) Errorln(_ ...interface{}) {} - -func (f *FakeLogger) Warnf(_ string, _ ...interface{}) {} -func (f *FakeLogger) Warnln(_ ...interface{}) {} - -func (f *FakeLogger) WithField(key string, value interface{}) log.Interface { - if key == "sourceIPs" { - f.sourceIPs = value.(string) +func newFakeLogger(level log.Level) *FakeLogger { + buf := bytes.NewBuffer(nil) + log := log.NewGoKitWriter(level, buf) + return &FakeLogger{ + logger: log, + buf: buf, } +} - return f +func (f *FakeLogger) Log(keyvals ...interface{}) error { + return f.logger.Log(keyvals...) } -func (f *FakeLogger) WithFields(_ log.Fields) log.Interface { - return f +func (f *FakeLogger) assertContains(t *testing.T, content string) { + require.True(t, bytes.Contains(f.buf.Bytes(), []byte(content))) +} + +func (f *FakeLogger) assertNotContains(t *testing.T, content string) { + require.False(t, bytes.Contains(f.buf.Bytes(), []byte(content))) } func TestLogSourceIPs(t *testing.T) { var level log.Level - require.NoError(t, level.Set("debug")) - fake := FakeLogger{} + require.NoError(t, level.Set("info")) + logger := newFakeLogger(level) cfg := Config{ HTTPListenNetwork: DefaultNetwork, HTTPListenAddress: "localhost", @@ -744,8 +742,8 @@ func TestLogSourceIPs(t *testing.T) { GRPCListenAddress: "localhost", HTTPMiddleware: []middleware.Interface{middleware.Logging}, MetricsNamespace: "testing_mux", - LogLevel: level, - Log: &fake, + LogLevel: "info", + Log: logger, LogSourceIPs: true, } server, err := New(cfg) @@ -760,14 +758,14 @@ func TestLogSourceIPs(t *testing.T) { }() defer server.Shutdown() - require.Empty(t, fake.sourceIPs) + logger.assertNotContains(t, "sourceIPs") req, err := http.NewRequest("GET", "http://127.0.0.1:9195/error500", nil) require.NoError(t, err) _, err = http.DefaultClient.Do(req) require.NoError(t, err) - require.Equal(t, fake.sourceIPs, "127.0.0.1") + logger.assertContains(t, "sourceIPs=127.0.0.1") } func TestStopWithDisabledSignalHandling(t *testing.T) { @@ -783,6 +781,7 @@ func TestStopWithDisabledSignalHandling(t *testing.T) { var test = func(t *testing.T, metricsNamespace string, handler SignalHandler) { cfg.SignalHandler = handler cfg.MetricsNamespace = metricsNamespace + cfg.LogLevel = "info" srv, err := New(cfg) require.NoError(t, err) diff --git a/signals/signals.go b/signals/signals.go index 75609a745..09f1ffbe8 100644 --- a/signals/signals.go +++ b/signals/signals.go @@ -10,7 +10,8 @@ import ( "runtime" "syscall" - "github.com/grafana/dskit/log" + "github.com/go-kit/log" + "github.com/go-kit/log/level" ) // SignalReceiver represents a subsystem/server/... that can be stopped or @@ -23,13 +24,13 @@ type SignalReceiver interface { // On SIGINT or SIGTERM it will exit, on SIGQUIT it // will dump goroutine stacks to the Logger. type Handler struct { - log log.Interface + log log.Logger receivers []SignalReceiver quit chan struct{} } // NewHandler makes a new Handler. -func NewHandler(log log.Interface, receivers ...SignalReceiver) *Handler { +func NewHandler(log log.Logger, receivers ...SignalReceiver) *Handler { return &Handler{ log: log, receivers: receivers, @@ -51,19 +52,19 @@ func (h *Handler) Loop() { for { select { case <-h.quit: - h.log.Infof("=== Handler.Stop()'d ===") + level.Info(h.log).Log("msg", "=== Handler.Stop()'d ===") return case sig := <-sigs: switch sig { case syscall.SIGINT, syscall.SIGTERM: - h.log.Infof("=== received SIGINT/SIGTERM ===\n*** exiting") + level.Info(h.log).Log("msg", "=== received SIGINT/SIGTERM ===\n*** exiting") for _, subsystem := range h.receivers { _ = subsystem.Stop() } return case syscall.SIGQUIT: stacklen := runtime.Stack(buf, true) - h.log.Infof("=== received SIGQUIT ===\n*** goroutine dump...\n%s\n*** end", buf[:stacklen]) + level.Info(h.log).Log("msg", "=== received SIGQUIT ===\n*** goroutine dump...\n%s\n*** end", buf[:stacklen]) } } } @@ -72,6 +73,6 @@ func (h *Handler) Loop() { // SignalHandlerLoop blocks until it receives a SIGINT, SIGTERM or SIGQUIT. // For SIGINT and SIGTERM, it exits; for SIGQUIT is print a goroutine stack // dump. -func SignalHandlerLoop(log log.Interface, ss ...SignalReceiver) { +func SignalHandlerLoop(log log.Logger, ss ...SignalReceiver) { NewHandler(log, ss...).Loop() } diff --git a/user/logging.go b/user/logging.go index 0db1946c8..a7d89b532 100644 --- a/user/logging.go +++ b/user/logging.go @@ -7,20 +7,20 @@ package user import ( "context" - "github.com/grafana/dskit/log" + "github.com/go-kit/log" ) // LogWith returns user and org information from the context as log fields. -func LogWith(ctx context.Context, log log.Interface) log.Interface { +func LogWith(ctx context.Context, logger log.Logger) log.Logger { userID, err := ExtractUserID(ctx) if err == nil { - log = log.WithField("userID", userID) + logger = log.With(logger, "userID", userID) } orgID, err := ExtractOrgID(ctx) if err == nil { - log = log.WithField("orgID", orgID) + logger = log.With(logger, "orgID", orgID) } - return log + return logger }