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 }