From 54f55b18e0b832e7fd5c92a60aba3a1a3af2ed82 Mon Sep 17 00:00:00 2001 From: Tom Wilkie Date: Thu, 19 Jul 2018 13:21:24 +0100 Subject: [PATCH] Abstract logging for the middleware (#96) * Move dedupe code to dedupe.go * Add unified logging interface. * Adapt middleware/, user/, signals/ and server/ to new logging interfaces. Allow user to specify logging implementation in server, if non is specified default to logrus. As part of this we need log level as server config, and for convenience we expose the server logger. * Update vendoring * Expose the various level types. Signed-off-by: Tom Wilkie --- Gopkg.lock | 72 ++++++++++++----- logging/dedupe.go | 137 +++++++++++++++++++++++++++++++ logging/global.go | 58 +++++++++++++ logging/gokit.go | 66 +++++++++++++++ logging/interface.go | 24 ++++++ logging/level.go | 64 +++++++++++++++ logging/logging.go | 161 ------------------------------------- logging/logrus.go | 74 +++++++++++++++++ logging/noop.go | 23 ++++++ middleware/grpc_logging.go | 16 ++-- middleware/logging.go | 24 +++--- server/server.go | 26 +++++- signals/signals.go | 13 ++- user/logging.go | 15 ++-- 14 files changed, 554 insertions(+), 219 deletions(-) create mode 100644 logging/dedupe.go create mode 100644 logging/global.go create mode 100644 logging/gokit.go create mode 100644 logging/interface.go create mode 100644 logging/level.go create mode 100644 logging/logrus.go create mode 100644 logging/noop.go diff --git a/Gopkg.lock b/Gopkg.lock index 0fe3ac30..79ab4aa4 100644 --- a/Gopkg.lock +++ b/Gopkg.lock @@ -17,8 +17,8 @@ "internal/sdkio", "internal/shareddefaults" ] - revision = "c7cd1ebe87257cde9b65112fc876b0339ea0ac30" - version = "v1.13.49" + revision = "554c8763b0d746658fe356cf368f5bee064aba09" + version = "v1.14.20" [[projects]] branch = "master" @@ -41,8 +41,29 @@ [[projects]] name = "github.com/go-ini/ini" packages = ["."] - revision = "6529cf7c58879c08d927016dde4477f18a0634cb" - version = "v1.36.0" + revision = "06f5f3d67269ccec1fe5fe4134ba6e982984f7f5" + version = "v1.37.0" + +[[projects]] + name = "github.com/go-kit/kit" + packages = [ + "log", + "log/level" + ] + revision = "ca4112baa34cb55091301bdc13b1420a122b1b9e" + version = "v0.7.0" + +[[projects]] + name = "github.com/go-logfmt/logfmt" + packages = ["."] + revision = "390ab7935ee28ec6b286364bba9b4dd6410cb3d5" + version = "v0.3.0" + +[[projects]] + name = "github.com/go-stack/stack" + packages = ["."] + revision = "259ab82a6cad3992b4e21ff5cac294ccb06474bc" + version = "v1.7.0" [[projects]] name = "github.com/golang/protobuf" @@ -75,6 +96,12 @@ packages = ["go/otgrpc"] revision = "8e809c8a86450a29b90dcc9efbf062d0fe6d9746" +[[projects]] + branch = "master" + name = "github.com/kr/logfmt" + packages = ["."] + revision = "b84e30acd515aadc4b783ad4ff83aff3299bdfe0" + [[projects]] name = "github.com/mattn/go-colorable" packages = ["."] @@ -90,8 +117,8 @@ [[projects]] name = "github.com/matttproud/golang_protobuf_extensions" packages = ["pbutil"] - revision = "3247c84500bff8d9fb6d579d800f20b3e091582c" - version = "v1.0.0" + revision = "c12348ce28de40eed0136aa2b644d0ee0650e56c" + version = "v1.0.1" [[projects]] branch = "master" @@ -109,7 +136,7 @@ branch = "master" name = "github.com/opentracing-contrib/go-stdlib" packages = ["nethttp"] - revision = "36723135187404d2f4002f4f189938565e64cc5c" + revision = "07a764486eb10927e8cf38337918a40d430524ee" [[projects]] name = "github.com/opentracing/opentracing-go" @@ -137,7 +164,7 @@ branch = "master" name = "github.com/prometheus/client_golang" packages = ["prometheus"] - revision = "82f5ff156b29e276022b1a958f7d385870fb9814" + revision = "d6a9817c4afc94d51115e4a30d449056a3fbf547" [[projects]] branch = "master" @@ -153,7 +180,7 @@ "internal/bitbucket.org/ww/goautoneg", "model" ] - revision = "d811d2e9bf898806ecfb6ef6296774b13ffc314c" + revision = "7600349dcfe1abd18d72d3a1770870d9800a7801" [[projects]] branch = "master" @@ -164,7 +191,7 @@ "nfs", "xfs" ] - revision = "8b1c2da0d56deffdbb9e48d4414b4e674bd8083e" + revision = "ae68e2d4c00fed4943b5f6698d504a5fe083da8a" [[projects]] name = "github.com/sercand/kuberesolver" @@ -187,8 +214,8 @@ "assert", "require" ] - revision = "12b6f73e6084dad08a7c6e575284b177ecafbc71" - version = "v1.2.1" + revision = "f35b8ab0b5a2cef36673838d662e249dd9c94686" + version = "v1.2.2" [[projects]] name = "github.com/uber/jaeger-client-go" @@ -229,7 +256,7 @@ branch = "master" name = "golang.org/x/crypto" packages = ["ssh/terminal"] - revision = "1a580b3eff7814fc9b40602fd35256c63b50f491" + revision = "a49355c7e3f8fe157a85be2f77e6e269a0f89602" [[projects]] branch = "master" @@ -243,7 +270,7 @@ "internal/timeseries", "trace" ] - revision = "2491c5de3490fced2f6cff376127c667efeed857" + revision = "32a936f46389aa10549d60bd7833e54b01685d09" [[projects]] branch = "master" @@ -252,7 +279,7 @@ "unix", "windows" ] - revision = "7c87d13f8e835d2fb3a70a2912c811ed0c1d241b" + revision = "ce36f3865eeb42541ce3f87f32f8462c5687befa" [[projects]] name = "golang.org/x/text" @@ -279,13 +306,13 @@ branch = "master" name = "golang.org/x/tools" packages = ["cover"] - revision = "48418e5732e1b1e2a10207c8007a5f959e422f20" + revision = "16f8f9bb720111f0b7b5c750acc28768620bb0c7" [[projects]] branch = "master" name = "google.golang.org/genproto" packages = ["googleapis/rpc/status"] - revision = "7bb2a897381c9c5ab2aeb8614f758d7766af68ff" + revision = "ff3583edef7de132f219f0efc00e097cabcc0ec0" [[projects]] name = "google.golang.org/grpc" @@ -294,15 +321,16 @@ "balancer", "balancer/base", "balancer/roundrobin", - "channelz", "codes", "connectivity", "credentials", "encoding", "encoding/proto", - "grpclb/grpc_lb_v1/messages", "grpclog", "internal", + "internal/backoff", + "internal/channelz", + "internal/grpcrand", "keepalive", "metadata", "naming", @@ -315,12 +343,12 @@ "tap", "transport" ] - revision = "41344da2231b913fa3d983840a57a6b1b7b631a1" - version = "v1.12.0" + revision = "168a6198bcb0ef175f7dacec0b8691fc141dc9b8" + version = "v1.13.0" [solve-meta] analyzer-name = "dep" analyzer-version = 1 - inputs-digest = "4c5d338c89a50a8734232d9f55fe96f3dcbd31f6f0387a3a1466404df4925090" + inputs-digest = "00ca48db1cbceb304f25a236a30e738a854dc916c58f79e8bfabb01587f6c4e5" solver-name = "gps-cdcl" solver-version = 1 diff --git a/logging/dedupe.go b/logging/dedupe.go new file mode 100644 index 00000000..caa523ef --- /dev/null +++ b/logging/dedupe.go @@ -0,0 +1,137 @@ +package logging + +import ( + "fmt" + "strings" + "sync" + "time" + + log "github.com/sirupsen/logrus" +) + +const ( + defaultDedupeInterval = time.Minute +) + +// SetupDeduplication should be performed after any other logging setup. +// For all logs less severe or equal to the given log level (but still higher than the logger's configured log level), +// these logs will be 'deduplicated'. What this means is that, excluding certain special fields like time, multiple +// identical log entries will be grouped up and a summary message emitted. +// For example, instead of: +// 00:00:00 INFO User 123 did xyz +// 00:00:10 INFO User 123 did xyz +// 00:00:25 INFO User 123 did xyz +// 00:00:55 INFO User 123 did xyz +// you would get: +// 00:00:00 INFO User 123 did xyz +// 00:01:00 INFO Repeated 3 times: User 123 did xyz +// The interval argument controls how long to wait for additional messages to arrive before reporting. +// Increase it to deduplicate more aggressively, decrease it to lower latency from a log occurring to it appearing. +// Set it to 0 to pick a sensible default value (recommended). +// NOTE: For simplicity and efficiency, fields are considered 'equal' if and only if their string representations (%v) are equal. +func SetupDeduplication(logLevel string, interval time.Duration) error { + dedupeLevel, err := log.ParseLevel(logLevel) + if err != nil { + return fmt.Errorf("Error parsing log level: %v", err) + } + if interval <= 0 { + interval = defaultDedupeInterval + } + + // We use a special Formatter to either format the log using the original formatter, or to return "" + // so nothing will be written for that event. The repeated entries are later logged along with a field flag + // that tells the formatter to ignore the message. + stdLogger := log.StandardLogger() + stdLogger.Formatter = newDedupeFormatter(stdLogger.Formatter, dedupeLevel, interval) + return nil +} + +type entryCount struct { + entry log.Entry + count int +} + +type dedupeFormatter struct { + innerFormatter log.Formatter + level log.Level + interval time.Duration + seen map[string]entryCount + lock sync.Mutex +} + +func newDedupeFormatter(innerFormatter log.Formatter, level log.Level, interval time.Duration) *dedupeFormatter { + return &dedupeFormatter{ + innerFormatter: innerFormatter, + level: level, + interval: interval, + seen: map[string]entryCount{}, + } +} + +func (f *dedupeFormatter) Format(entry *log.Entry) ([]byte, error) { + if f.shouldLog(entry) { + b, err := f.innerFormatter.Format(entry) + return b, err + } + return []byte{}, nil +} + +func (f *dedupeFormatter) shouldLog(entry *log.Entry) bool { + if _, ok := entry.Data["deduplicated"]; ok { + // ignore our own logs about deduped messages + return true + } + if entry.Level < f.level { + // ignore logs more severe than our level + return true + } + key := fmt.Sprintf("%s %s", entry.Message, fieldsToString(entry.Data)) + f.lock.Lock() + defer f.lock.Unlock() + if ec, ok := f.seen[key]; ok { + // already seen, increment count and do not log + ec.count++ + f.seen[key] = ec + return false + } + // New message, log it but add it to seen. + // We need to copy because the pointer ceases to be valid after we return from Format + f.seen[key] = entryCount{entry: *entry} + go f.evictEntry(key) // queue to evict later + return true +} + +// Wait for interval seconds then evict the entry and send the log +func (f *dedupeFormatter) evictEntry(key string) { + time.Sleep(f.interval) + var ec entryCount + func() { + f.lock.Lock() + defer f.lock.Unlock() + ec = f.seen[key] + delete(f.seen, key) + }() + if ec.count == 0 { + return + } + entry := log.WithFields(ec.entry.Data).WithField("deduplicated", ec.count) + message := fmt.Sprintf("Repeated %d times: %s", ec.count, ec.entry.Message) + // There's no way to choose the log level dynamically, so we have to do this hack + map[log.Level]func(args ...interface{}){ + log.PanicLevel: entry.Panic, + log.FatalLevel: entry.Fatal, + log.ErrorLevel: entry.Error, + log.WarnLevel: entry.Warn, + log.InfoLevel: entry.Info, + log.DebugLevel: entry.Debug, + }[ec.entry.Level](message) +} + +func fieldsToString(data log.Fields) string { + parts := make([]string, 0, len(data)) + // traversal order here is arbitrary but stable, which is fine for our purposes + for k, v := range data { + parts = append(parts, fmt.Sprintf("%s=%v", k, v)) + } + return strings.Join(parts, " ") +} diff --git a/logging/global.go b/logging/global.go new file mode 100644 index 00000000..5dd69baa --- /dev/null +++ b/logging/global.go @@ -0,0 +1,58 @@ +package logging + +var global Interface = Noop() + +// Global returns the global logger. +func Global() Interface { + 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/logging/gokit.go b/logging/gokit.go new file mode 100644 index 00000000..b5137fa4 --- /dev/null +++ b/logging/gokit.go @@ -0,0 +1,66 @@ +package logging + +import ( + "fmt" + "os" + + "github.com/go-kit/kit/log" + "github.com/go-kit/kit/log/level" +) + +// NewGoKit creates a new Interface backed by a GoKit logger +func NewGoKit(l Level) Interface { + logger := log.NewLogfmtLogger(log.NewSyncWriter(os.Stderr)) + logger = level.NewFilter(logger, l.Gokit) + logger = log.With(logger, "ts", log.DefaultTimestampUTC, "caller", log.DefaultCaller) + return gokit{logger} +} + +// GoKit wraps an existing gokit Logger. +func GoKit(logger log.Logger) Interface { + return gokit{logger} +} + +type gokit struct { + log.Logger +} + +func (g gokit) Debugf(format string, args ...interface{}) { + level.Debug(g.Logger).Log("msg", fmt.Sprintf(format, args...)) +} +func (g gokit) Debugln(args ...interface{}) { + level.Debug(g.Logger).Log("msg", fmt.Sprintln(args...)) +} + +func (g gokit) Infof(format string, args ...interface{}) { + level.Info(g.Logger).Log("msg", fmt.Sprintf(format, args...)) +} +func (g gokit) Infoln(args ...interface{}) { + level.Info(g.Logger).Log("msg", fmt.Sprintln(args...)) +} + +func (g gokit) Warnf(format string, args ...interface{}) { + level.Warn(g.Logger).Log("msg", fmt.Sprintf(format, args...)) +} +func (g gokit) Warnln(args ...interface{}) { + level.Warn(g.Logger).Log("msg", fmt.Sprintln(args...)) +} + +func (g gokit) Errorf(format string, args ...interface{}) { + level.Error(g.Logger).Log("msg", fmt.Sprintf(format, args...)) +} +func (g gokit) Errorln(args ...interface{}) { + level.Error(g.Logger).Log("msg", fmt.Sprintln(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} +} diff --git a/logging/interface.go b/logging/interface.go new file mode 100644 index 00000000..f4625e47 --- /dev/null +++ b/logging/interface.go @@ -0,0 +1,24 @@ +package logging + +// 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/logging/level.go b/logging/level.go new file mode 100644 index 00000000..e9d60e63 --- /dev/null +++ b/logging/level.go @@ -0,0 +1,64 @@ +package logging + +// 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/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. +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 +} + +// Set updates the value of the allowed level. +func (l *Level) Set(s string) error { + switch s { + case "debug": + l.Logrus = logrus.DebugLevel + l.Gokit = level.AllowDebug() + case "info": + l.Logrus = logrus.InfoLevel + l.Gokit = level.AllowInfo() + case "warn": + l.Logrus = logrus.WarnLevel + l.Gokit = level.AllowWarn() + case "error": + l.Logrus = logrus.ErrorLevel + l.Gokit = level.AllowError() + default: + return errors.Errorf("unrecognized log level %q", s) + } + + l.s = s + return nil +} diff --git a/logging/logging.go b/logging/logging.go index 1047e712..744b76c7 100644 --- a/logging/logging.go +++ b/logging/logging.go @@ -1,24 +1,13 @@ package logging import ( - "bytes" "fmt" "os" - "strings" - "sync" - "time" - - "golang.org/x/net/context" log "github.com/sirupsen/logrus" - "github.com/weaveworks/common/user" "github.com/weaveworks/promrus" ) -const ( - defaultDedupeInterval = time.Minute -) - // Setup configures logging output to stderr, sets the log level and sets the formatter. func Setup(logLevel string) error { log.SetOutput(os.Stderr) @@ -35,153 +24,3 @@ func Setup(logLevel string) error { log.AddHook(hook) return nil } - -// SetupDeduplication should be performed after any other logging setup. -// For all logs less severe or equal to the given log level (but still higher than the logger's configured log level), -// these logs will be 'deduplicated'. What this means is that, excluding certain special fields like time, multiple -// identical log entries will be grouped up and a summary message emitted. -// For example, instead of: -// 00:00:00 INFO User 123 did xyz -// 00:00:10 INFO User 123 did xyz -// 00:00:25 INFO User 123 did xyz -// 00:00:55 INFO User 123 did xyz -// you would get: -// 00:00:00 INFO User 123 did xyz -// 00:01:00 INFO Repeated 3 times: User 123 did xyz -// The interval argument controls how long to wait for additional messages to arrive before reporting. -// Increase it to deduplicate more aggressively, decrease it to lower latency from a log occurring to it appearing. -// Set it to 0 to pick a sensible default value (recommended). -// NOTE: For simplicity and efficiency, fields are considered 'equal' if and only if their string representations (%v) are equal. -func SetupDeduplication(logLevel string, interval time.Duration) error { - dedupeLevel, err := log.ParseLevel(logLevel) - if err != nil { - return fmt.Errorf("Error parsing log level: %v", err) - } - if interval <= 0 { - interval = defaultDedupeInterval - } - - // We use a special Formatter to either format the log using the original formatter, or to return "" - // so nothing will be written for that event. The repeated entries are later logged along with a field flag - // that tells the formatter to ignore the message. - stdLogger := log.StandardLogger() - stdLogger.Formatter = newDedupeFormatter(stdLogger.Formatter, dedupeLevel, interval) - return nil -} - -type textFormatter struct{} - -// Based off logrus.TextFormatter, which behaves completely -// differently when you don't want colored output -func (f *textFormatter) Format(entry *log.Entry) ([]byte, error) { - b := &bytes.Buffer{} - - levelText := strings.ToUpper(entry.Level.String())[0:4] - timeStamp := entry.Time.Format("2006/01/02 15:04:05.000000") - fmt.Fprintf(b, "%s: %s %s", levelText, timeStamp, entry.Message) - if len(entry.Data) > 0 { - b.WriteString(" " + fieldsToString(entry.Data)) - } - - b.WriteByte('\n') - return b.Bytes(), nil -} - -// With returns a log entry with common Weaveworks logging information. -// -// e.g. -// logger := logging.With(ctx) -// logger.Errorf("Some error") -func With(ctx context.Context) *log.Entry { - return log.WithFields(user.LogFields(ctx)) -} - -type entryCount struct { - entry log.Entry - count int -} - -type dedupeFormatter struct { - innerFormatter log.Formatter - level log.Level - interval time.Duration - seen map[string]entryCount - lock sync.Mutex -} - -func newDedupeFormatter(innerFormatter log.Formatter, level log.Level, interval time.Duration) *dedupeFormatter { - return &dedupeFormatter{ - innerFormatter: innerFormatter, - level: level, - interval: interval, - seen: map[string]entryCount{}, - } -} - -func (f *dedupeFormatter) Format(entry *log.Entry) ([]byte, error) { - if f.shouldLog(entry) { - b, err := f.innerFormatter.Format(entry) - return b, err - } - return []byte{}, nil -} - -func (f *dedupeFormatter) shouldLog(entry *log.Entry) bool { - if _, ok := entry.Data["deduplicated"]; ok { - // ignore our own logs about deduped messages - return true - } - if entry.Level < f.level { - // ignore logs more severe than our level - return true - } - key := fmt.Sprintf("%s %s", entry.Message, fieldsToString(entry.Data)) - f.lock.Lock() - defer f.lock.Unlock() - if ec, ok := f.seen[key]; ok { - // already seen, increment count and do not log - ec.count++ - f.seen[key] = ec - return false - } - // New message, log it but add it to seen. - // We need to copy because the pointer ceases to be valid after we return from Format - f.seen[key] = entryCount{entry: *entry} - go f.evictEntry(key) // queue to evict later - return true -} - -// Wait for interval seconds then evict the entry and send the log -func (f *dedupeFormatter) evictEntry(key string) { - time.Sleep(f.interval) - var ec entryCount - func() { - f.lock.Lock() - defer f.lock.Unlock() - ec = f.seen[key] - delete(f.seen, key) - }() - if ec.count == 0 { - return - } - entry := log.WithFields(ec.entry.Data).WithField("deduplicated", ec.count) - message := fmt.Sprintf("Repeated %d times: %s", ec.count, ec.entry.Message) - // There's no way to choose the log level dynamically, so we have to do this hack - map[log.Level]func(args ...interface{}){ - log.PanicLevel: entry.Panic, - log.FatalLevel: entry.Fatal, - log.ErrorLevel: entry.Error, - log.WarnLevel: entry.Warn, - log.InfoLevel: entry.Info, - log.DebugLevel: entry.Debug, - }[ec.entry.Level](message) -} - -func fieldsToString(data log.Fields) string { - parts := make([]string, 0, len(data)) - // traversal order here is arbitrary but stable, which is fine for our purposes - for k, v := range data { - parts = append(parts, fmt.Sprintf("%s=%v", k, v)) - } - return strings.Join(parts, " ") -} diff --git a/logging/logrus.go b/logging/logrus.go new file mode 100644 index 00000000..7896b358 --- /dev/null +++ b/logging/logrus.go @@ -0,0 +1,74 @@ +package logging + +import ( + "bytes" + "fmt" + "os" + "strings" + + "github.com/sirupsen/logrus" +) + +// NewLogrus makes a new Interface backed by a logrus logger +func NewLogrus(level Level) Interface { + log := logrus.New() + log.Out = os.Stderr + log.Level = level.Logrus + log.Formatter = &textFormatter{} + return logrusLogger{log} +} + +// 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 logusEntry{ + Entry: l.Logger.WithField(key, value), + } +} + +func (l logrusLogger) WithFields(fields Fields) Interface { + return logusEntry{ + Entry: l.Logger.WithFields(map[string]interface{}(fields)), + } +} + +type logusEntry struct { + *logrus.Entry +} + +func (l logusEntry) WithField(key string, value interface{}) Interface { + return logusEntry{ + Entry: l.Entry.WithField(key, value), + } +} + +func (l logusEntry) WithFields(fields Fields) Interface { + return logusEntry{ + Entry: l.Entry.WithFields(map[string]interface{}(fields)), + } +} + +type textFormatter struct{} + +// Based off logrus.TextFormatter, which behaves completely +// differently when you don't want colored output +func (f *textFormatter) Format(entry *logrus.Entry) ([]byte, error) { + b := &bytes.Buffer{} + + levelText := strings.ToUpper(entry.Level.String())[0:4] + timeStamp := entry.Time.Format("2006/01/02 15:04:05.000000") + fmt.Fprintf(b, "%s: %s %s", levelText, timeStamp, entry.Message) + if len(entry.Data) > 0 { + b.WriteString(" " + fieldsToString(entry.Data)) + } + + b.WriteByte('\n') + return b.Bytes(), nil +} diff --git a/logging/noop.go b/logging/noop.go new file mode 100644 index 00000000..8b7201ca --- /dev/null +++ b/logging/noop.go @@ -0,0 +1,23 @@ +package logging + +// Noop logger. +func Noop() Interface { + return noop{} +} + +type noop struct{} + +func (noop) Debugf(format string, args ...interface{}) {} +func (noop) Debugln(args ...interface{}) {} +func (noop) Infof(format string, args ...interface{}) {} +func (noop) Infoln(args ...interface{}) {} +func (noop) Warnf(format string, args ...interface{}) {} +func (noop) Warnln(args ...interface{}) {} +func (noop) Errorf(format string, args ...interface{}) {} +func (noop) Errorln(args ...interface{}) {} +func (noop) WithField(key string, value interface{}) Interface { + return noop{} +} +func (noop) WithFields(Fields) Interface { + return noop{} +} diff --git a/middleware/grpc_logging.go b/middleware/grpc_logging.go index f55d50cb..bc9c9f37 100644 --- a/middleware/grpc_logging.go +++ b/middleware/grpc_logging.go @@ -3,17 +3,21 @@ package middleware import ( "time" - log "github.com/sirupsen/logrus" "golang.org/x/net/context" "google.golang.org/grpc" "github.com/weaveworks/common/logging" + "github.com/weaveworks/common/user" ) -const gRPC = "gRPC" +const ( + gRPC = "gRPC" + errorKey = "err" +) // GRPCServerLog logs grpc requests, errors, and latency. type GRPCServerLog struct { + Log logging.Interface // WithRequest will log the entire request rather than just the error WithRequest bool } @@ -22,12 +26,12 @@ type GRPCServerLog struct { func (s GRPCServerLog) UnaryServerInterceptor(ctx context.Context, req interface{}, info *grpc.UnaryServerInfo, handler grpc.UnaryHandler) (interface{}, error) { begin := time.Now() resp, err := handler(ctx, req) - entry := logging.With(ctx).WithFields(log.Fields{"method": info.FullMethod, "duration": time.Since(begin)}) + entry := user.LogWith(ctx, s.Log).WithFields(logging.Fields{"method": info.FullMethod, "duration": time.Since(begin)}) if err != nil { if s.WithRequest { entry = entry.WithField("request", req) } - entry.WithError(err).Warn(gRPC) + entry.WithField(errorKey, err).Warnln(gRPC) } else { entry.Debugf("%s (success)", gRPC) } @@ -38,9 +42,9 @@ func (s GRPCServerLog) UnaryServerInterceptor(ctx context.Context, req interface func (s GRPCServerLog) StreamServerInterceptor(srv interface{}, ss grpc.ServerStream, info *grpc.StreamServerInfo, handler grpc.StreamHandler) error { begin := time.Now() err := handler(srv, ss) - entry := logging.With(ss.Context()).WithFields(log.Fields{"method": info.FullMethod, "duration": time.Since(begin)}) + entry := user.LogWith(ss.Context(), s.Log).WithFields(logging.Fields{"method": info.FullMethod, "duration": time.Since(begin)}) if err != nil { - entry.WithError(err).Warn(gRPC) + entry.WithField(errorKey, err).Warnln(gRPC) } else { entry.Debugf("%s (success)", gRPC) } diff --git a/middleware/logging.go b/middleware/logging.go index 4dbc049b..fc669d0e 100644 --- a/middleware/logging.go +++ b/middleware/logging.go @@ -6,19 +6,19 @@ import ( "net/http/httputil" "time" - log "github.com/sirupsen/logrus" - + "github.com/weaveworks/common/logging" "github.com/weaveworks/common/user" ) // Log middleware logs http requests type Log struct { + Log logging.Interface LogRequestHeaders bool // LogRequestHeaders true -> dump http headers at debug log level } // logWithRequest information from the request and context as fields. -func logWithRequest(r *http.Request) *log.Entry { - return log.WithFields(user.LogFields(r.Context())) +func (l Log) logWithRequest(r *http.Request) logging.Interface { + return user.LogWith(r.Context(), l.Log) } // Wrap implements Middleware @@ -30,27 +30,29 @@ func (l Log) Wrap(next http.Handler) http.Handler { headers, err := httputil.DumpRequest(r, false) if err != nil { headers = nil - logWithRequest(r).Errorf("Could not dump request headers: %v", err) + l.logWithRequest(r).Errorf("Could not dump request headers: %v", err) } var buf bytes.Buffer wrapped := newBadResponseLoggingWriter(w, &buf) next.ServeHTTP(wrapped, r) statusCode := wrapped.statusCode if 100 <= statusCode && statusCode < 500 || statusCode == http.StatusBadGateway || statusCode == http.StatusServiceUnavailable { - logWithRequest(r).Debugf("%s %s (%d) %s", r.Method, uri, statusCode, time.Since(begin)) + l.logWithRequest(r).Debugf("%s %s (%d) %s", r.Method, uri, statusCode, time.Since(begin)) if l.LogRequestHeaders && headers != nil { - logWithRequest(r).Debugf("Is websocket request: %v\n%s", IsWSHandshakeRequest(r), string(headers)) + l.logWithRequest(r).Debugf("Is websocket request: %v\n%s", IsWSHandshakeRequest(r), string(headers)) } } else { - logWithRequest(r).Warnf("%s %s (%d) %s", r.Method, uri, statusCode, time.Since(begin)) + l.logWithRequest(r).Warnf("%s %s (%d) %s", r.Method, uri, statusCode, time.Since(begin)) if headers != nil { - logWithRequest(r).Warnf("Is websocket request: %v\n%s", IsWSHandshakeRequest(r), string(headers)) + l.logWithRequest(r).Warnf("Is websocket request: %v\n%s", IsWSHandshakeRequest(r), string(headers)) } - logWithRequest(r).Warnf("Response: %s", buf.Bytes()) + l.logWithRequest(r).Warnf("Response: %s", buf.Bytes()) } }) } // Logging middleware logs each HTTP request method, path, response code and // duration for all HTTP requests. -var Logging = Log{} +var Logging = Log{ + Log: logging.Global(), +} diff --git a/server/server.go b/server/server.go index 82632285..3064136a 100644 --- a/server/server.go +++ b/server/server.go @@ -14,13 +14,13 @@ import ( "github.com/opentracing-contrib/go-stdlib/nethttp" "github.com/opentracing/opentracing-go" "github.com/prometheus/client_golang/prometheus" - log "github.com/sirupsen/logrus" "golang.org/x/net/context" "google.golang.org/grpc" "github.com/weaveworks/common/httpgrpc" httpgrpc_server "github.com/weaveworks/common/httpgrpc/server" "github.com/weaveworks/common/instrument" + "github.com/weaveworks/common/logging" "github.com/weaveworks/common/middleware" "github.com/weaveworks/common/signals" ) @@ -43,6 +43,9 @@ type Config struct { GRPCMiddleware []grpc.UnaryServerInterceptor GRPCStreamMiddleware []grpc.StreamServerInterceptor HTTPMiddleware []middleware.Interface + + LogLevel logging.Level + Log logging.Interface } // RegisterFlags adds the flags required to config this to the given FlagSet @@ -54,6 +57,7 @@ func (cfg *Config) RegisterFlags(f *flag.FlagSet) { f.DurationVar(&cfg.HTTPServerReadTimeout, "server.http-read-timeout", 5*time.Second, "Read timeout for HTTP server") f.DurationVar(&cfg.HTTPServerWriteTimeout, "server.http-write-timeout", 5*time.Second, "Write timeout for HTTP server") f.DurationVar(&cfg.HTTPServerIdleTimeout, "server.http-idle-timeout", 120*time.Second, "Idle timeout for HTTP server") + cfg.LogLevel.RegisterFlags(f) } // Server wraps a HTTP and gRPC server, and some common initialization. @@ -68,6 +72,7 @@ type Server struct { HTTP *mux.Router GRPC *grpc.Server + Log logging.Interface } // New makes a new Server @@ -92,8 +97,18 @@ func New(cfg Config) (*Server, error) { }, []string{"method", "route", "status_code", "ws"}) prometheus.MustRegister(requestDuration) + // If user doesn't supply a logging implementation, by default instantiate + // logrus. + log := cfg.Log + if log == nil { + log = logging.NewLogrus(cfg.LogLevel) + } + // Setup gRPC server - serverLog := middleware.GRPCServerLog{WithRequest: !cfg.ExcludeRequestInLog} + serverLog := middleware.GRPCServerLog{ + WithRequest: !cfg.ExcludeRequestInLog, + Log: log, + } grpcMiddleware := []grpc.UnaryServerInterceptor{ serverLog.UnaryServerInterceptor, middleware.UnaryServerInstrumentInterceptor(requestDuration), @@ -125,7 +140,9 @@ func New(cfg Config) (*Server, error) { RegisterInstrumentation(router) } httpMiddleware := []middleware.Interface{ - middleware.Log{}, + middleware.Log{ + Log: log, + }, middleware.Instrument{ Duration: requestDuration, RouteMatcher: router, @@ -147,10 +164,11 @@ func New(cfg Config) (*Server, error) { httpListener: httpListener, grpcListener: grpcListener, httpServer: httpServer, - handler: signals.NewHandler(log.StandardLogger()), + handler: signals.NewHandler(log), HTTP: router, GRPC: grpcServer, + Log: log, }, nil } diff --git a/signals/signals.go b/signals/signals.go index cca60b9b..1c5569a4 100644 --- a/signals/signals.go +++ b/signals/signals.go @@ -5,6 +5,8 @@ import ( "os/signal" "runtime" "syscall" + + "github.com/weaveworks/common/logging" ) // SignalReceiver represents a subsystem/server/... that can be stopped or @@ -13,22 +15,17 @@ type SignalReceiver interface { Stop() error } -// Logger is something to log too. -type Logger interface { - Infof(format string, args ...interface{}) -} - // Handler handles signals, can be interrupted. // On SIGINT or SIGTERM it will exit, on SIGQUIT it // will dump goroutine stacks to the Logger. type Handler struct { - log Logger + log logging.Interface receivers []SignalReceiver quit chan struct{} } // NewHandler makes a new Handler. -func NewHandler(log Logger, receivers ...SignalReceiver) *Handler { +func NewHandler(log logging.Interface, receivers ...SignalReceiver) *Handler { return &Handler{ log: log, receivers: receivers, @@ -70,6 +67,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 Logger, ss ...SignalReceiver) { +func SignalHandlerLoop(log logging.Interface, ss ...SignalReceiver) { NewHandler(log, ss...).Loop() } diff --git a/user/logging.go b/user/logging.go index 05123df5..b873945b 100644 --- a/user/logging.go +++ b/user/logging.go @@ -3,19 +3,20 @@ package user import ( "golang.org/x/net/context" - log "github.com/sirupsen/logrus" + "github.com/weaveworks/common/logging" ) -// LogFields returns user and org information from the context as log fields. -func LogFields(ctx context.Context) log.Fields { - fields := log.Fields{} +// LogWith returns user and org information from the context as log fields. +func LogWith(ctx context.Context, log logging.Interface) logging.Interface { userID, err := ExtractUserID(ctx) if err == nil { - fields["userID"] = userID + log = log.WithField("userID", userID) } + orgID, err := ExtractOrgID(ctx) if err == nil { - fields["orgID"] = orgID + log = log.WithField("orgID", orgID) } - return fields + + return log }