From b0e42ef9df2a858770ca5205cd15a6963c87a754 Mon Sep 17 00:00:00 2001 From: Joe Elliott Date: Thu, 13 Aug 2020 11:57:31 -0400 Subject: [PATCH 1/5] Added rate limited logger Signed-off-by: Joe Elliott --- go.mod | 2 ++ go.sum | 5 +++++ 2 files changed, 7 insertions(+) diff --git a/go.mod b/go.mod index d72adcda..8a86bdb4 100644 --- a/go.mod +++ b/go.mod @@ -38,8 +38,10 @@ require ( github.com/uber/jaeger-lib v1.5.1-0.20181102163054-1fc5c315e03c github.com/weaveworks/promrus v1.2.0 golang.org/x/net v0.0.0-20200202094626-16171245cfb2 + golang.org/x/time v0.0.0-20191024005414-555d28b269f0 golang.org/x/tools v0.0.0-20200216192241-b320d3a0f5a2 google.golang.org/genproto v0.0.0-20190819201941-24fa4b261c55 // indirect google.golang.org/grpc v1.26.0 gopkg.in/yaml.v2 v2.2.8 + gotest.tools v2.2.0+incompatible ) diff --git a/go.sum b/go.sum index de35f58d..9e4135c5 100644 --- a/go.sum +++ b/go.sum @@ -117,6 +117,7 @@ github.com/google/btree v1.0.0/go.mod h1:lNA+9X1NB3Zf8V7Ke586lFgjr2dZNuvo3lPJSGZ github.com/google/go-cmp v0.2.0/go.mod h1:oXzfMopK8JAjlY9xF4vHSVASa0yLyX7SntLO5aqRK0M= github.com/google/go-cmp v0.3.0/go.mod h1:8QqcDgzrUqlUb/G2PQTWiueGozuR1884gddMywk6iLU= github.com/google/go-cmp v0.3.1/go.mod h1:8QqcDgzrUqlUb/G2PQTWiueGozuR1884gddMywk6iLU= +github.com/google/go-cmp v0.4.0 h1:xsAVV57WRhGj6kEIi8ReJzQlHHqcBYCElAvkovg3B/4= github.com/google/go-cmp v0.4.0/go.mod h1:v8dTdLbMG2kIc/vJvl+f65V22dbkXbowE6jgT/gNBxE= github.com/google/gofuzz v1.0.0/go.mod h1:dBl0BpW6vV/+mYPU4Po3pmUjxk6FQPldtuIdl/M65Eg= github.com/google/renameio v0.1.0/go.mod h1:KWCgfxg9yswjAJkECMjeO8J8rahYeXnNhOm40UhjYkI= @@ -456,6 +457,7 @@ golang.org/x/text v0.3.0/go.mod h1:NqM8EUOU14njkJ3fqMW+pc6Ldnwhi/IjpwHt7yyuwOQ= golang.org/x/text v0.3.2 h1:tW2bmiBqwgJj/UpqtC8EpXEZVYOwU0yG4iWbprSVAcs= golang.org/x/text v0.3.2/go.mod h1:bEr9sfX3Q8Zfm5fL9x+3itogRgK3+ptLWKqgva+5dAk= golang.org/x/time v0.0.0-20180412165947-fbb02b2291d2/go.mod h1:tRJNPiyCQ0inRvYxbN9jk5I+vvW/OXSQhTDSoE431IQ= +golang.org/x/time v0.0.0-20191024005414-555d28b269f0 h1:/5xXl8Y5W96D+TtHSlonuFqGHIWVuyCkGJLwGh9JJFs= golang.org/x/time v0.0.0-20191024005414-555d28b269f0/go.mod h1:tRJNPiyCQ0inRvYxbN9jk5I+vvW/OXSQhTDSoE431IQ= golang.org/x/tools v0.0.0-20180221164845-07fd8470d635/go.mod h1:n7NCudcB/nEzxVGmLbDWY5pfWTLqBcC2KZ6jyYvM4mQ= golang.org/x/tools v0.0.0-20180828015842-6cd1fcedba52/go.mod h1:n7NCudcB/nEzxVGmLbDWY5pfWTLqBcC2KZ6jyYvM4mQ= @@ -519,6 +521,9 @@ gopkg.in/yaml.v2 v2.2.4/go.mod h1:hI93XBmqTisBFMUTm0b8Fm+jr3Dg1NNxqwp+5A1VGuI= gopkg.in/yaml.v2 v2.2.5/go.mod h1:hI93XBmqTisBFMUTm0b8Fm+jr3Dg1NNxqwp+5A1VGuI= gopkg.in/yaml.v2 v2.2.8 h1:obN1ZagJSUGI0Ek/LBmuj4SNLPfIny3KsKFopxRdj10= gopkg.in/yaml.v2 v2.2.8/go.mod h1:hI93XBmqTisBFMUTm0b8Fm+jr3Dg1NNxqwp+5A1VGuI= +gotest.tools v1.4.0 h1:BjtEgfuw8Qyd+jPvQz8CfoxiO/UjFEidWinwEXZiWv0= +gotest.tools v2.2.0+incompatible h1:VsBPFP1AI068pPrMxtb/S8Zkgf9xEmTLJjfM+P5UIEo= +gotest.tools v2.2.0+incompatible/go.mod h1:DsYFclhRJ6vuDpmuTbkuFWG+y2sxOXAzmJt81HFBacw= honnef.co/go/tools v0.0.0-20180728063816-88497007e858/go.mod h1:rf3lG4BRIbNafJWhAfAdb/ePZxsR/4RtNHQocxwk9r4= honnef.co/go/tools v0.0.0-20190102054323-c2f93a96b099/go.mod h1:rf3lG4BRIbNafJWhAfAdb/ePZxsR/4RtNHQocxwk9r4= honnef.co/go/tools v0.0.0-20190523083050-ea95bdfd59fc/go.mod h1:rf3lG4BRIbNafJWhAfAdb/ePZxsR/4RtNHQocxwk9r4= From 64270969a5045b503da50fb0a5ea4b95661837bb Mon Sep 17 00:00:00 2001 From: Joe Elliott Date: Fri, 14 Aug 2020 08:46:54 -0400 Subject: [PATCH 2/5] Added rate limited logger and used it Signed-off-by: Joe Elliott --- logging/ratelimit.go | 79 +++++++++++++++++++++++++++++++++++++++ logging/ratelimit_test.go | 43 +++++++++++++++++++++ middleware/logging.go | 28 +++++++++++--- server/server.go | 16 ++++++-- 4 files changed, 157 insertions(+), 9 deletions(-) create mode 100644 logging/ratelimit.go create mode 100644 logging/ratelimit_test.go diff --git a/logging/ratelimit.go b/logging/ratelimit.go new file mode 100644 index 00000000..409f4fa9 --- /dev/null +++ b/logging/ratelimit.go @@ -0,0 +1,79 @@ +package logging + +import "golang.org/x/time/rate" + +type rateLimitedLogger struct { + next Interface + limiter *rate.Limiter +} + +// NewRateLimitedLogger returns a logger.Interface that is limited to a number +// of logs per second +func NewRateLimitedLogger(logger Interface, logsPerSecond rate.Limit) Interface { + return &rateLimitedLogger{ + next: logger, + limiter: rate.NewLimiter(logsPerSecond, 1), + } +} + +func (l *rateLimitedLogger) Debugf(format string, args ...interface{}) { + if l.limiter.Allow() { + l.next.Debugf(format, args...) + } +} + +func (l *rateLimitedLogger) Debugln(args ...interface{}) { + if l.limiter.Allow() { + l.next.Debugln(args...) + } +} + +func (l *rateLimitedLogger) Infof(format string, args ...interface{}) { + if l.limiter.Allow() { + l.next.Infof(format, args...) + } +} + +func (l *rateLimitedLogger) Infoln(args ...interface{}) { + if l.limiter.Allow() { + l.next.Infoln(args...) + } +} + +func (l *rateLimitedLogger) Errorf(format string, args ...interface{}) { + if l.limiter.Allow() { + l.next.Errorf(format, args...) + } +} + +func (l *rateLimitedLogger) Errorln(args ...interface{}) { + if l.limiter.Allow() { + l.next.Errorln(args...) + } +} + +func (l *rateLimitedLogger) Warnf(format string, args ...interface{}) { + if l.limiter.Allow() { + l.next.Warnf(format, args...) + } +} + +func (l *rateLimitedLogger) Warnln(args ...interface{}) { + if l.limiter.Allow() { + l.next.Warnln(args...) + } +} + +func (l *rateLimitedLogger) WithField(key string, value interface{}) Interface { + return &rateLimitedLogger{ + next: l.next.WithField(key, value), + limiter: rate.NewLimiter(l.limiter.Limit(), 0), + } +} + +func (l *rateLimitedLogger) WithFields(f Fields) Interface { + return &rateLimitedLogger{ + next: l.next.WithFields(f), + limiter: rate.NewLimiter(l.limiter.Limit(), 0), + } +} diff --git a/logging/ratelimit_test.go b/logging/ratelimit_test.go new file mode 100644 index 00000000..4c53501c --- /dev/null +++ b/logging/ratelimit_test.go @@ -0,0 +1,43 @@ +package logging + +import ( + "testing" + + "gotest.tools/assert" +) + +type counterLogger struct { + count int +} + +func (c *counterLogger) Debugf(format string, args ...interface{}) { c.count++ } +func (c *counterLogger) Debugln(args ...interface{}) { c.count++ } +func (c *counterLogger) Infof(format string, args ...interface{}) { c.count++ } +func (c *counterLogger) Infoln(args ...interface{}) { c.count++ } +func (c *counterLogger) Warnf(format string, args ...interface{}) { c.count++ } +func (c *counterLogger) Warnln(args ...interface{}) { c.count++ } +func (c *counterLogger) Errorf(format string, args ...interface{}) { c.count++ } +func (c *counterLogger) Errorln(args ...interface{}) { c.count++ } +func (c *counterLogger) WithField(key string, value interface{}) Interface { + return c +} +func (c *counterLogger) WithFields(Fields) Interface { + return c +} + +func TestRateLimitedLoggerLogs(t *testing.T) { + c := &counterLogger{} + r := NewRateLimitedLogger(c, 1) + + r.Errorln("asdf") + assert.Equal(t, 1, c.count) +} + +func TestRateLimitedLoggerLimits(t *testing.T) { + c := &counterLogger{} + r := NewRateLimitedLogger(c, 1) + + r.Errorln("asdf") + r.Infoln("asdf") + assert.Equal(t, 1, c.count) +} diff --git a/middleware/logging.go b/middleware/logging.go index 79368f9d..580c902a 100644 --- a/middleware/logging.go +++ b/middleware/logging.go @@ -13,18 +13,23 @@ import ( // Log middleware logs http requests type Log struct { - Log logging.Interface - LogRequestHeaders bool // LogRequestHeaders true -> dump http headers at debug log level + Log logging.Interface + HighVolumeErrorLog logging.Interface + LogRequestHeaders bool // LogRequestHeaders true -> dump http headers at debug log level } // logWithRequest information from the request and context as fields. func (l Log) logWithRequest(r *http.Request) logging.Interface { + return l.logWithRequestAndLog(r, l.Log) +} + +func (l Log) logWithRequestAndLog(r *http.Request, logger logging.Interface) logging.Interface { traceID, ok := ExtractTraceID(r.Context()) if ok { - l.Log = l.Log.WithField("traceID", traceID) + logger = logger.WithField("traceID", traceID) } - return user.LogWith(r.Context(), l.Log) + return user.LogWith(r.Context(), logger) } // Wrap implements Middleware @@ -53,11 +58,16 @@ func (l Log) Wrap(next http.Handler) http.Handler { return } - if 100 <= statusCode && statusCode < 500 || statusCode == http.StatusBadGateway || statusCode == http.StatusServiceUnavailable { + if 100 <= statusCode && statusCode < 500 { l.logWithRequest(r).Debugf("%s %s (%d) %s", r.Method, uri, statusCode, time.Since(begin)) if l.LogRequestHeaders && headers != nil { l.logWithRequest(r).Debugf("ws: %v; %s", IsWSHandshakeRequest(r), string(headers)) } + } else if statusCode == http.StatusBadGateway || statusCode == http.StatusServiceUnavailable { + l.logHighVolumeError(r, "%s %s (%d) %s", r.Method, uri, statusCode, time.Since(begin)) + if l.LogRequestHeaders && headers != nil { + l.logHighVolumeError(r, "ws: %v; %s", IsWSHandshakeRequest(r), string(headers)) + } } else { l.logWithRequest(r).Warnf("%s %s (%d) %s Response: %q ws: %v; %s", r.Method, uri, statusCode, time.Since(begin), buf.Bytes(), IsWSHandshakeRequest(r), headers) @@ -65,6 +75,14 @@ func (l Log) Wrap(next http.Handler) http.Handler { }) } +func (l Log) logHighVolumeError(r *http.Request, format string, args ...interface{}) { + if l.HighVolumeErrorLog != nil { + l.logWithRequestAndLog(r, l.HighVolumeErrorLog).Warnf(format, args...) + } else { + l.logWithRequest(r).Debugf(format, args...) + } +} + // Logging middleware logs each HTTP request method, path, response code and // duration for all HTTP requests. var Logging = Log{ diff --git a/server/server.go b/server/server.go index 4dc8ae0e..dde9394d 100644 --- a/server/server.go +++ b/server/server.go @@ -19,6 +19,7 @@ import ( node_https "github.com/prometheus/node_exporter/https" "golang.org/x/net/context" "golang.org/x/net/netutil" + "golang.org/x/time/rate" "google.golang.org/grpc" "google.golang.org/grpc/credentials" "google.golang.org/grpc/keepalive" @@ -76,9 +77,10 @@ type Config struct { GRPCServerTime time.Duration `yaml:"grpc_server_keepalive_time"` GRPCServerTimeout time.Duration `yaml:"grpc_server_keepalive_timeout"` - LogFormat logging.Format `yaml:"log_format"` - LogLevel logging.Level `yaml:"log_level"` - Log logging.Interface `yaml:"-"` + LogFormat logging.Format `yaml:"log_format"` + LogErrorRate int `yaml:"log_error_rate"` + LogLevel logging.Level `yaml:"log_level"` + Log logging.Interface `yaml:"-"` // If not set, default signal handler is used. SignalHandler SignalHandler `yaml:"-"` @@ -164,6 +166,11 @@ func New(cfg Config) (*Server, error) { log = logging.NewLogrus(cfg.LogLevel) } + var highVolumeErrorLog logging.Interface + if cfg.LogErrorRate > 0 { + highVolumeErrorLog = logging.NewRateLimitedLogger(log, rate.Limit(cfg.LogErrorRate)) + } + // Setup TLS var httpTLSConfig *tls.Config if len(cfg.HTTPTLSConfig.TLSCertPath) > 0 && len(cfg.HTTPTLSConfig.TLSKeyPath) > 0 { @@ -254,7 +261,8 @@ func New(cfg Config) (*Server, error) { RouteMatcher: router, }, middleware.Log{ - Log: log, + Log: log, + HighVolumeErrorLog: highVolumeErrorLog, }, middleware.Instrument{ Duration: requestDuration, From bc9ae8d1a7526dcc702d8699d77d65abcea05ea6 Mon Sep 17 00:00:00 2001 From: Joe Elliott Date: Thu, 20 Aug 2020 12:11:17 -0400 Subject: [PATCH 3/5] For high volume errors log everything on the same line Signed-off-by: Joe Elliott --- middleware/logging.go | 7 ++++--- 1 file changed, 4 insertions(+), 3 deletions(-) diff --git a/middleware/logging.go b/middleware/logging.go index a86f6f92..7e66d19b 100644 --- a/middleware/logging.go +++ b/middleware/logging.go @@ -73,9 +73,10 @@ func (l Log) Wrap(next http.Handler) http.Handler { l.logWithRequest(r).Debugf("ws: %v; %s", IsWSHandshakeRequest(r), string(headers)) } } else if statusCode == http.StatusBadGateway || statusCode == http.StatusServiceUnavailable { - l.logHighVolumeError(r, "%s %s (%d) %s", r.Method, uri, statusCode, time.Since(begin)) - if l.LogRequestHeaders && headers != nil { - l.logHighVolumeError(r, "ws: %v; %s", IsWSHandshakeRequest(r), string(headers)) + if l.LogRequestHeaders { + l.logHighVolumeError(r, "%s %s (%d) %s %v %s", r.Method, uri, statusCode, time.Since(begin), IsWSHandshakeRequest(r), string(headers)) + } else { + l.logHighVolumeError(r, "%s %s (%d) %s", r.Method, uri, statusCode, time.Since(begin)) } } else { l.logWithRequest(r).Warnf("%s %s (%d) %s Response: %q ws: %v; %s", From db20483219381a1a5f78569112d005d54e03918b Mon Sep 17 00:00:00 2001 From: Joe Elliott Date: Mon, 14 Sep 2020 11:26:29 -0400 Subject: [PATCH 4/5] Fixed burst size on With logger Signed-off-by: Joe Elliott --- logging/ratelimit.go | 4 ++-- logging/ratelimit_test.go | 10 ++++++++++ 2 files changed, 12 insertions(+), 2 deletions(-) diff --git a/logging/ratelimit.go b/logging/ratelimit.go index 409f4fa9..62ac1982 100644 --- a/logging/ratelimit.go +++ b/logging/ratelimit.go @@ -67,13 +67,13 @@ func (l *rateLimitedLogger) Warnln(args ...interface{}) { func (l *rateLimitedLogger) WithField(key string, value interface{}) Interface { return &rateLimitedLogger{ next: l.next.WithField(key, value), - limiter: rate.NewLimiter(l.limiter.Limit(), 0), + limiter: rate.NewLimiter(l.limiter.Limit(), 1), } } func (l *rateLimitedLogger) WithFields(f Fields) Interface { return &rateLimitedLogger{ next: l.next.WithFields(f), - limiter: rate.NewLimiter(l.limiter.Limit(), 0), + limiter: rate.NewLimiter(l.limiter.Limit(), 1), } } diff --git a/logging/ratelimit_test.go b/logging/ratelimit_test.go index 4c53501c..a5bf366f 100644 --- a/logging/ratelimit_test.go +++ b/logging/ratelimit_test.go @@ -41,3 +41,13 @@ func TestRateLimitedLoggerLimits(t *testing.T) { r.Infoln("asdf") assert.Equal(t, 1, c.count) } + +func TestRateLimitedLoggerWith(t *testing.T) { + c := &counterLogger{} + r := NewRateLimitedLogger(c, 1) + r2 := r.WithField("key", "value") + + r2.Errorln("asdf") + r2.Warnln("asdf") + assert.Equal(t, 1, c.count) +} From 54c934b82fe1e629728a15a77638310a0510b352 Mon Sep 17 00:00:00 2001 From: Joe Elliott Date: Mon, 14 Sep 2020 13:06:15 -0400 Subject: [PATCH 5/5] Use the same limiter for derived loggers Signed-off-by: Joe Elliott --- logging/ratelimit.go | 4 ++-- logging/ratelimit_test.go | 3 ++- 2 files changed, 4 insertions(+), 3 deletions(-) diff --git a/logging/ratelimit.go b/logging/ratelimit.go index 62ac1982..583934e9 100644 --- a/logging/ratelimit.go +++ b/logging/ratelimit.go @@ -67,13 +67,13 @@ func (l *rateLimitedLogger) Warnln(args ...interface{}) { func (l *rateLimitedLogger) WithField(key string, value interface{}) Interface { return &rateLimitedLogger{ next: l.next.WithField(key, value), - limiter: rate.NewLimiter(l.limiter.Limit(), 1), + limiter: l.limiter, } } func (l *rateLimitedLogger) WithFields(f Fields) Interface { return &rateLimitedLogger{ next: l.next.WithFields(f), - limiter: rate.NewLimiter(l.limiter.Limit(), 1), + limiter: l.limiter, } } diff --git a/logging/ratelimit_test.go b/logging/ratelimit_test.go index a5bf366f..a9bc22c9 100644 --- a/logging/ratelimit_test.go +++ b/logging/ratelimit_test.go @@ -42,11 +42,12 @@ func TestRateLimitedLoggerLimits(t *testing.T) { assert.Equal(t, 1, c.count) } -func TestRateLimitedLoggerWith(t *testing.T) { +func TestRateLimitedLoggerWithFields(t *testing.T) { c := &counterLogger{} r := NewRateLimitedLogger(c, 1) r2 := r.WithField("key", "value") + r.Errorf("asdf") r2.Errorln("asdf") r2.Warnln("asdf") assert.Equal(t, 1, c.count)