diff --git a/NOTICE.txt b/NOTICE.txt index 9721ea4..6b2455a 100644 --- a/NOTICE.txt +++ b/NOTICE.txt @@ -2282,6 +2282,43 @@ THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE. +-------------------------------------------------------------------------------- +Dependency : golang.org/x/time +Version: v0.8.0 +Licence type (autodetected): BSD-3-Clause +-------------------------------------------------------------------------------- + +Contents of probable licence file $GOMODCACHE/golang.org/x/time@v0.8.0/LICENSE: + +Copyright 2009 The Go Authors. + +Redistribution and use in source and binary forms, with or without +modification, are permitted provided that the following conditions are +met: + + * Redistributions of source code must retain the above copyright +notice, this list of conditions and the following disclaimer. + * Redistributions in binary form must reproduce the above +copyright notice, this list of conditions and the following disclaimer +in the documentation and/or other materials provided with the +distribution. + * Neither the name of Google LLC nor the names of its +contributors may be used to endorse or promote products derived from +this software without specific prior written permission. + +THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS +"AS IS" AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT +LIMITED TO, THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR +A PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT +OWNER OR CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL, +SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT +LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF USE, +DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON ANY +THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT +(INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE +OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE. + + -------------------------------------------------------------------------------- Dependency : gopkg.in/mcuadros/go-syslog.v2 Version: v2.3.0 diff --git a/go.mod b/go.mod index 8fa9e49..752e31f 100644 --- a/go.mod +++ b/go.mod @@ -24,6 +24,7 @@ require ( golang.org/x/net v0.26.0 golang.org/x/sys v0.21.0 golang.org/x/text v0.16.0 + golang.org/x/time v0.8.0 gopkg.in/mcuadros/go-syslog.v2 v2.3.0 gopkg.in/yaml.v2 v2.4.0 ) diff --git a/go.sum b/go.sum index 7254cdc..9eedf28 100644 --- a/go.sum +++ b/go.sum @@ -195,6 +195,8 @@ golang.org/x/text v0.9.0/go.mod h1:e1OnstbJyHTd6l/uOt8jFFHp6TRDWZR/bV3emEE/zU8= golang.org/x/text v0.14.0/go.mod h1:18ZOQIKpY8NJVqYksKHtTdi31H5itFRjB5/qKTNYzSU= golang.org/x/text v0.16.0 h1:a94ExnEXNtEwYLGJSIUxnWoxoRz/ZcCsV63ROupILh4= golang.org/x/text v0.16.0/go.mod h1:GhwF1Be+LQoKShO3cGOHzqOgRrGaYc9AvblQOmPVHnI= +golang.org/x/time v0.8.0 h1:9i3RxcPv3PZnitoVGMPDKZSq1xW1gK1Xy3ArNOGZfEg= +golang.org/x/time v0.8.0/go.mod h1:3BpzKBy/shNhVucY/MWOyx10tF3SFh9QdLuxbVysPQM= golang.org/x/tools v0.0.0-20180917221912-90fa682c2a6e/go.mod h1:n7NCudcB/nEzxVGmLbDWY5pfWTLqBcC2KZ6jyYvM4mQ= golang.org/x/tools v0.0.0-20190311212946-11955173bddd/go.mod h1:LCzVGOaR6xXOjkQ3onu1FJEFr0SW1gC7cKk1uF8kGRs= golang.org/x/tools v0.0.0-20191119224855-298f0cb1881e/go.mod h1:b+2E5dAYhXwXZwtnZ6UAqBI28+e2cm9otk0dWdXHAEo= diff --git a/logp/logger.go b/logp/logger.go index 5b66e19..c49b8f7 100644 --- a/logp/logger.go +++ b/logp/logger.go @@ -21,10 +21,12 @@ import ( "bytes" "fmt" "io" + "time" "go.elastic.co/ecszap" "go.uber.org/zap" "go.uber.org/zap/zapcore" + "golang.org/x/time/rate" ) // LogOption configures a Logger. @@ -32,16 +34,17 @@ type LogOption = zap.Option // Logger logs messages to the configured output. type Logger struct { - logger *zap.Logger - sugar *zap.SugaredLogger + logger *zap.Logger + sugar *zap.SugaredLogger + limiter *rate.Sometimes } func newLogger(rootLogger *zap.Logger, selector string, options ...LogOption) *Logger { log := rootLogger. - WithOptions(zap.AddCallerSkip(1)). + WithOptions(zap.AddCallerSkip(3)). WithOptions(options...). Named(selector) - return &Logger{log, log.Sugar()} + return &Logger{log, log.Sugar(), nil} } // NewLogger returns a new Logger labeled with the name of the selector. This @@ -81,62 +84,70 @@ func NewInMemory(selector string, encCfg zapcore.EncoderConfig) (*Logger, *bytes return logger, &buff } +func (l *Logger) do(f func()) { + if l.limiter != nil { + l.limiter.Do(f) + return + } + f() +} + // WithOptions returns a clone of l with options applied. func (l *Logger) WithOptions(options ...LogOption) *Logger { cloned := l.logger.WithOptions(options...) - return &Logger{cloned, cloned.Sugar()} + return &Logger{cloned, cloned.Sugar(), nil} } // With creates a child logger and adds structured context to it. Fields added // to the child don't affect the parent, and vice versa. func (l *Logger) With(args ...interface{}) *Logger { sugar := l.sugar.With(args...) - return &Logger{sugar.Desugar(), sugar} + return &Logger{sugar.Desugar(), sugar, nil} } // Named adds a new path segment to the logger's name. Segments are joined by // periods. func (l *Logger) Named(name string) *Logger { logger := l.logger.Named(name) - return &Logger{logger, logger.Sugar()} + return &Logger{logger, logger.Sugar(), nil} } // Sprint // Debug uses fmt.Sprint to construct and log a message. func (l *Logger) Debug(args ...interface{}) { - l.sugar.Debug(args...) + l.do(func() { l.sugar.Debug(args...) }) } // Info uses fmt.Sprint to construct and log a message. func (l *Logger) Info(args ...interface{}) { - l.sugar.Info(args...) + l.do(func() { l.sugar.Info(args...) }) } // Warn uses fmt.Sprint to construct and log a message. func (l *Logger) Warn(args ...interface{}) { - l.sugar.Warn(args...) + l.do(func() { l.sugar.Warn(args...) }) } // Error uses fmt.Sprint to construct and log a message. func (l *Logger) Error(args ...interface{}) { - l.sugar.Error(args...) + l.do(func() { l.sugar.Error(args...) }) } // Fatal uses fmt.Sprint to construct and log a message, then calls os.Exit(1). func (l *Logger) Fatal(args ...interface{}) { - l.sugar.Fatal(args...) + l.do(func() { l.sugar.Fatal(args...) }) } // Panic uses fmt.Sprint to construct and log a message, then panics. func (l *Logger) Panic(args ...interface{}) { - l.sugar.Panic(args...) + l.do(func() { l.sugar.Panic(args...) }) } // DPanic uses fmt.Sprint to construct and log a message. In development, the // logger then panics. func (l *Logger) DPanic(args ...interface{}) { - l.sugar.DPanic(args...) + l.do(func() { l.sugar.DPanic(args...) }) } // IsDebug checks to see if the given logger is Debug enabled. @@ -148,38 +159,38 @@ func (l *Logger) IsDebug() bool { // Debugf uses fmt.Sprintf to construct and log a message. func (l *Logger) Debugf(format string, args ...interface{}) { - l.sugar.Debugf(format, args...) + l.do(func() { l.sugar.Debugf(format, args...) }) } // Infof uses fmt.Sprintf to log a templated message. func (l *Logger) Infof(format string, args ...interface{}) { - l.sugar.Infof(format, args...) + l.do(func() { l.sugar.Infof(format, args...) }) } // Warnf uses fmt.Sprintf to log a templated message. func (l *Logger) Warnf(format string, args ...interface{}) { - l.sugar.Warnf(format, args...) + l.do(func() { l.sugar.Warnf(format, args...) }) } // Errorf uses fmt.Sprintf to log a templated message. func (l *Logger) Errorf(format string, args ...interface{}) { - l.sugar.Errorf(format, args...) + l.do(func() { l.sugar.Errorf(format, args...) }) } // Fatalf uses fmt.Sprintf to log a templated message, then calls os.Exit(1). func (l *Logger) Fatalf(format string, args ...interface{}) { - l.sugar.Fatalf(format, args...) + l.do(func() { l.sugar.Fatalf(format, args...) }) } // Panicf uses fmt.Sprintf to log a templated message, then panics. func (l *Logger) Panicf(format string, args ...interface{}) { - l.sugar.Panicf(format, args...) + l.do(func() { l.sugar.Panicf(format, args...) }) } // DPanicf uses fmt.Sprintf to log a templated message. In development, the // logger then panics. func (l *Logger) DPanicf(format string, args ...interface{}) { - l.sugar.DPanicf(format, args...) + l.do(func() { l.sugar.DPanicf(format, args...) }) } // With context (reflection based) @@ -189,7 +200,7 @@ func (l *Logger) DPanicf(format string, args ...interface{}) { // to the log message will be inferred by the value's type. To explicitly // specify a type you can pass a Field such as logp.Stringer. func (l *Logger) Debugw(msg string, keysAndValues ...interface{}) { - l.sugar.Debugw(msg, keysAndValues...) + l.do(func() { l.sugar.Debugw(msg, keysAndValues...) }) } // Infow logs a message with some additional context. The additional context @@ -197,7 +208,7 @@ func (l *Logger) Debugw(msg string, keysAndValues ...interface{}) { // to the log message will be inferred by the value's type. To explicitly // specify a type you can pass a Field such as logp.Stringer. func (l *Logger) Infow(msg string, keysAndValues ...interface{}) { - l.sugar.Infow(msg, keysAndValues...) + l.do(func() { l.sugar.Infow(msg, keysAndValues...) }) } // Warnw logs a message with some additional context. The additional context @@ -205,7 +216,7 @@ func (l *Logger) Infow(msg string, keysAndValues ...interface{}) { // to the log message will be inferred by the value's type. To explicitly // specify a type you can pass a Field such as logp.Stringer. func (l *Logger) Warnw(msg string, keysAndValues ...interface{}) { - l.sugar.Warnw(msg, keysAndValues...) + l.do(func() { l.sugar.Warnw(msg, keysAndValues...) }) } // Errorw logs a message with some additional context. The additional context @@ -213,7 +224,7 @@ func (l *Logger) Warnw(msg string, keysAndValues ...interface{}) { // to the log message will be inferred by the value's type. To explicitly // specify a type you can pass a Field such as logp.Stringer. func (l *Logger) Errorw(msg string, keysAndValues ...interface{}) { - l.sugar.Errorw(msg, keysAndValues...) + l.do(func() { l.sugar.Errorw(msg, keysAndValues...) }) } // Fatalw logs a message with some additional context, then calls os.Exit(1). @@ -222,7 +233,7 @@ func (l *Logger) Errorw(msg string, keysAndValues ...interface{}) { // type. To explicitly specify a type you can pass a Field such as // logp.Stringer. func (l *Logger) Fatalw(msg string, keysAndValues ...interface{}) { - l.sugar.Fatalw(msg, keysAndValues...) + l.do(func() { l.sugar.Fatalw(msg, keysAndValues...) }) } // Panicw logs a message with some additional context, then panics. The @@ -230,7 +241,7 @@ func (l *Logger) Fatalw(msg string, keysAndValues ...interface{}) { // to write the value to the log message will be inferred by the value's type. // To explicitly specify a type you can pass a Field such as logp.Stringer. func (l *Logger) Panicw(msg string, keysAndValues ...interface{}) { - l.sugar.Panicw(msg, keysAndValues...) + l.do(func() { l.sugar.Panicw(msg, keysAndValues...) }) } // DPanicw logs a message with some additional context. The logger panics only @@ -239,7 +250,7 @@ func (l *Logger) Panicw(msg string, keysAndValues ...interface{}) { // be inferred by the value's type. To explicitly specify a type you can pass a // Field such as logp.Stringer. func (l *Logger) DPanicw(msg string, keysAndValues ...interface{}) { - l.sugar.DPanicw(msg, keysAndValues...) + l.do(func() { l.sugar.DPanicw(msg, keysAndValues...) }) } // Recover stops a panicking goroutine and logs an Error. @@ -269,6 +280,36 @@ func (l *Logger) Close() error { return nil } +func (l *Logger) rateLimiter() *rate.Sometimes { + limiter := l.limiter + if limiter == nil { + limiter = &rate.Sometimes{} + } + + return limiter +} + +// Throttled returns a new Logger that logs at most once every period. +func (l *Logger) Throttled(period time.Duration) *Logger { + limiter := l.rateLimiter() + limiter.Interval = period + return &Logger{l.logger, l.sugar, limiter} +} + +// Sampled returns a new Logger that logs every nth log message. +func (l *Logger) Sampled(nth int) *Logger { + limiter := l.rateLimiter() + limiter.Every = nth + return &Logger{l.logger, l.sugar, limiter} +} + +// Limited returns a new Logger that logs the first n log messages. +func (l *Logger) Limited(n int) *Logger { + limiter := l.rateLimiter() + limiter.First = n + return &Logger{l.logger, l.sugar, limiter} +} + // L returns an unnamed global logger. func L() *Logger { return loadLogger().logger diff --git a/logp/logger_test.go b/logp/logger_test.go index 256ff92..2d0bb83 100644 --- a/logp/logger_test.go +++ b/logp/logger_test.go @@ -18,8 +18,12 @@ package logp import ( + "math" + "runtime" "strings" + "sync" "testing" + "time" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" @@ -79,3 +83,308 @@ func TestNewInMemory(t *testing.T) { assert.Contains(t, logs[3], "error_key") assert.Contains(t, logs[3], "error_val") } + +func TestThrottledLogger(t *testing.T) { + l, buff := NewInMemory("in_memory", ConsoleEncoderConfig()) + + log := l.Throttled(10 * time.Millisecond) + + log.Info("logged") + log.Info("throttled") + + logs := strings.Split(strings.TrimSpace(buff.String()), "\n") + require.Len(t, logs, 1, "expected 1 log entry") + require.Contains(t, logs[0], "logged") + + time.Sleep(10 * time.Millisecond) + + log.Warn("logged") + log.Info("throttled") + log.Info("throttled") + + logs = strings.Split(strings.TrimSpace(buff.String()), "\n") + require.Len(t, logs, 2, "expected 2 log entries") + require.Contains(t, logs[1], "logged") +} + +func TestSampledLogger(t *testing.T) { + l, buff := NewInMemory("in_memory", ConsoleEncoderConfig()) + + log := l.Sampled(2) + + log.Info("1") + log.Info("2") + log.Info("3") + + logs := strings.Split(strings.TrimSpace(buff.String()), "\n") + require.Len(t, logs, 2, "expected 2 log entries") + require.Contains(t, logs[0], "1") + require.Contains(t, logs[1], "3") + + log.Info("4") + log.Info("5") + + logs = strings.Split(strings.TrimSpace(buff.String()), "\n") + require.Len(t, logs, 3, "expected 3 log entries") + require.Contains(t, logs[2], "5") +} + +func TestLimitedLogger(t *testing.T) { + l, buff := NewInMemory("in_memory", ConsoleEncoderConfig()) + + log := l.Limited(2) + + log.Info("1") + log.Info("2") + log.Info("3") + + logs := strings.Split(strings.TrimSpace(buff.String()), "\n") + require.Len(t, logs, 2, "expected 2 log entries") + require.Contains(t, logs[0], "1") + require.Contains(t, logs[1], "2") + + log.Info("4") + log.Info("5") + + logs = strings.Split(strings.TrimSpace(buff.String()), "\n") + require.Len(t, logs, 2, "expected 2 log entries") +} + +func TestSampledLimited(t *testing.T) { + l, buff := NewInMemory("in_memory", ConsoleEncoderConfig()) + + log := l.Sampled(2).Limited(3) + + log.Info("1") + log.Info("2") + log.Info("3") + + logs := strings.Split(strings.TrimSpace(buff.String()), "\n") + require.Len(t, logs, 3, "expected 3 log entries") + require.Contains(t, logs[0], "1") + require.Contains(t, logs[1], "2") + require.Contains(t, logs[2], "3") + + log.Info("4") + log.Info("5") + + logs = strings.Split(strings.TrimSpace(buff.String()), "\n") + require.Len(t, logs, 4, "expected 4 log entries") + require.Contains(t, logs[3], "5") +} + +func TestSampledThrottledLogger(t *testing.T) { + l, buff := NewInMemory("in_memory", ConsoleEncoderConfig()) + + log := l.Throttled(10 * time.Millisecond).Sampled(2) + + log.Info("logged") + log.Info("throttled") + + logs := strings.Split(strings.TrimSpace(buff.String()), "\n") + require.Len(t, logs, 1, "expected 1 log entry") + require.Contains(t, logs[0], "logged") + + time.Sleep(10 * time.Millisecond) + + log.Warn("discarded by sampler") + log.Info("throttled") + + logs = strings.Split(strings.TrimSpace(buff.String()), "\n") + require.Len(t, logs, 2, "expected no new log entries") + + time.Sleep(10 * time.Millisecond) + + log.Warn("logged by sampler") + log.Info("throttled") + + logs = strings.Split(strings.TrimSpace(buff.String()), "\n") + require.Len(t, logs, 3, "expected 3 log entries") + require.Contains(t, logs[2], "logged") +} + +func BenchmarkLogger(b *testing.B) { + l := newLogger(zap.NewNop(), "") + + b.Run("default", func(b *testing.B) { + log := l.Named("default") + b.ResetTimer() + for i := 0; i < b.N; i++ { + log.Info("message") + } + }) + + b.Run("sampled", func(b *testing.B) { + log := l.Sampled(1) + b.ResetTimer() + for i := 0; i < b.N; i++ { + log.Info("message") + } + }) + + b.Run("throttled", func(b *testing.B) { + log := l.Throttled(1 * time.Nanosecond) + b.ResetTimer() + for i := 0; i < b.N; i++ { + log.Info("message") + } + }) + + b.Run("limited", func(b *testing.B) { + log := l.Limited(math.MaxInt) + b.ResetTimer() + for i := 0; i < b.N; i++ { + log.Info("message") + } + }) +} + +func BenchmarkConcurrentLoggerSynthetic(b *testing.B) { + l := newLogger(zap.NewNop(), "") + + b.Run("default", func(b *testing.B) { + var group sync.WaitGroup + log := l.Named("default") + b.ResetTimer() + for i := runtime.NumCPU(); i > 0; i-- { + group.Add(1) + go func() { + for i := 0; i < b.N; i++ { + log.Info("message") + } + defer group.Done() + }() + } + }) + + b.Run("sampled", func(b *testing.B) { + var group sync.WaitGroup + log := l.Sampled(1) + b.ResetTimer() + for i := runtime.NumCPU(); i > 0; i-- { + group.Add(1) + go func() { + for i := 0; i < b.N; i++ { + log.Info("message") + } + defer group.Done() + }() + } + group.Wait() + }) + + b.Run("throttled", func(b *testing.B) { + var group sync.WaitGroup + log := l.Throttled(1 * time.Nanosecond) + b.ResetTimer() + for i := runtime.NumCPU(); i > 0; i-- { + group.Add(1) + go func() { + for i := 0; i < b.N; i++ { + log.Info("message") + } + defer group.Done() + }() + } + group.Wait() + }) + + b.Run("limited", func(b *testing.B) { + var group sync.WaitGroup + log := l.Limited(math.MaxInt) + b.ResetTimer() + for i := runtime.NumCPU(); i > 0; i-- { + group.Add(1) + go func() { + for i := 0; i < b.N; i++ { + log.Info("message") + } + defer group.Done() + }() + } + group.Wait() + }) +} + +func BenchmarkConcurrentLoggerRealistic(b *testing.B) { + l := newLogger(zap.NewNop(), "") + + b.Run("default", func(b *testing.B) { + var group sync.WaitGroup + log := l.Named("default") + b.ResetTimer() + for i := runtime.NumCPU(); i > 0; i-- { + group.Add(1) + go func() { + for i := 0; i < b.N; i++ { + log.Info("message") + } + defer group.Done() + }() + } + }) + + b.Run("sampled-every-4", func(b *testing.B) { + var group sync.WaitGroup + log := l.Sampled(4) + b.ResetTimer() + for i := runtime.NumCPU(); i > 0; i-- { + group.Add(1) + go func() { + for i := 0; i < b.N; i++ { + log.Info("message") + } + defer group.Done() + }() + } + group.Wait() + }) + + b.Run("throttled-1-per-second", func(b *testing.B) { + var group sync.WaitGroup + log := l.Throttled(1 * time.Second) + b.ResetTimer() + for i := runtime.NumCPU(); i > 0; i-- { + group.Add(1) + go func() { + for i := 0; i < b.N; i++ { + log.Info("message") + } + defer group.Done() + }() + } + group.Wait() + }) + + b.Run("limited-first-10", func(b *testing.B) { + var group sync.WaitGroup + log := l.Limited(10) + b.ResetTimer() + for i := runtime.NumCPU(); i > 0; i-- { + group.Add(1) + go func() { + for i := 0; i < b.N; i++ { + log.Info("message") + } + defer group.Done() + }() + } + group.Wait() + }) + + b.Run("sampled-1-out-of-2-limited-first-10-throttled-1-per-second", func(b *testing.B) { + var group sync.WaitGroup + log := l.Limited(10).Sampled(2).Throttled(1 * time.Second) + b.ResetTimer() + for i := runtime.NumCPU(); i > 0; i-- { + group.Add(1) + go func() { + for i := 0; i < b.N; i++ { + log.Info("message") + } + defer group.Done() + }() + } + group.Wait() + }) +}