From bb69d7c6ca17eac9813871444fb49bc10bf49f46 Mon Sep 17 00:00:00 2001 From: Benji Rewis Date: Mon, 18 Nov 2024 16:29:56 -0500 Subject: [PATCH 1/3] POC dedupe-logs --- components/motor/fake/motor.go | 28 +++++++++++-- logging/impl.go | 61 +++++++++++++++++++++++++++ logging/logging.go | 77 +++++++++++++++++++++++++--------- 3 files changed, 142 insertions(+), 24 deletions(-) diff --git a/components/motor/fake/motor.go b/components/motor/fake/motor.go index 68b082ca215..d90d733195c 100644 --- a/components/motor/fake/motor.go +++ b/components/motor/fake/motor.go @@ -18,6 +18,7 @@ import ( "go.viam.com/rdk/logging" "go.viam.com/rdk/operation" "go.viam.com/rdk/resource" + "go.viam.com/utils" ) var ( @@ -79,7 +80,6 @@ func init() { // direction. type Motor struct { resource.Named - resource.TriviallyCloseable mu sync.Mutex powerPct float64 @@ -93,14 +93,29 @@ type Motor struct { OpMgr *operation.SingleOperationManager Logger logging.Logger + + logWorkers *utils.StoppableWorkers } // NewMotor creates a new fake motor. func NewMotor(ctx context.Context, deps resource.Dependencies, conf resource.Config, logger logging.Logger) (motor.Motor, error) { + logWorker := func(ctx context.Context) { + for { + if ctx.Err() != nil { + logger.Info("stopping log worker") + return + } + + logger.Info("here is an annoying spammy message") + time.Sleep(10 * time.Millisecond) + } + } + m := &Motor{ - Named: conf.ResourceName().AsNamed(), - Logger: logger, - OpMgr: operation.NewSingleOperationManager(), + Named: conf.ResourceName().AsNamed(), + Logger: logger, + OpMgr: operation.NewSingleOperationManager(), + logWorkers: utils.NewBackgroundStoppableWorkers(logWorker), } if err := m.Reconfigure(ctx, deps, conf); err != nil { return nil, err @@ -431,3 +446,8 @@ func (m *Motor) IsMoving(ctx context.Context) (bool, error) { defer m.mu.Unlock() return math.Abs(m.powerPct) >= 0.005, nil } + +func (m *Motor) Close(ctx context.Context) error { + m.logWorkers.Stop() + return nil +} diff --git a/logging/impl.go b/logging/impl.go index 5492386699f..41ee35803ee 100644 --- a/logging/impl.go +++ b/logging/impl.go @@ -15,6 +15,14 @@ import ( "go.uber.org/zap/zaptest" ) +const ( + // Window duration over which to consider log messages "noisy." + noisyMessageWindowDuration = 5 * time.Second + // Count threshold within `noisyMessageWindowDuration` after which to + // consider log messages "noisy." + noisyMessageCountThreshold = 3 +) + type ( impl struct { name string @@ -26,6 +34,15 @@ type ( // avoid that. This function is a no-op for non-test loggers. See `NewTestAppender` // documentation for more details. testHelper func() + + // Whether or not to de-duplicate noisy logs. + dedupNoisyLogs bool + // Map of messages to counts of that message being `Write`ten within window. + recentMessageCounts map[string]int + // Map of messages to last `LogEntry` with that message within window. + recentMessageEntries map[string]LogEntry + // Start of current window. + recentMessageWindowStart time.Time } // LogEntry embeds a zapcore Entry and slice of Fields. @@ -84,6 +101,14 @@ func (imp *impl) Sublogger(subname string) Logger { imp.appenders, imp.registry, imp.testHelper, + // Inherit _whether_ we should deduplicate noisy logs from parent. However, + // subloggers should handle their own de-duplication with their own maps + // and windows. This design avoids races and allows logs with identical + // messages from different loggers to be considered unique. + imp.dedupNoisyLogs, + make(map[string]int), + make(map[string]LogEntry), + time.Now(), } // If there are multiple callers racing to create the same logger name (e.g: `viam.networking`), @@ -198,6 +223,42 @@ func (imp *impl) shouldLog(logLevel Level) bool { } func (imp *impl) Write(entry *LogEntry) { + if imp.dedupNoisyLogs { + // If we have have entered a new recentMessage window, output noisy logs from + // the last window. + if time.Since(imp.recentMessageWindowStart) > noisyMessageWindowDuration { + for message, count := range imp.recentMessageCounts { + if count > noisyMessageCountThreshold { + collapsedEntry := imp.recentMessageEntries[entry.Message] + collapsedEntry.Message = fmt.Sprintf("Message logged %d times in past %v: %s", + count, noisyMessageWindowDuration, message) + + imp.testHelper() + for _, appender := range imp.appenders { + err := appender.Write(collapsedEntry.Entry, collapsedEntry.Fields) + if err != nil { + fmt.Fprint(os.Stderr, err) + } + } + } + } + + // Clear maps and reset window. + clear(imp.recentMessageCounts) + clear(imp.recentMessageEntries) + imp.recentMessageWindowStart = time.Now() + } + + // Track entry in recentMessage maps. + imp.recentMessageCounts[entry.Message]++ + imp.recentMessageEntries[entry.Message] = *entry + + if imp.recentMessageCounts[entry.Message] > noisyMessageCountThreshold { + // If entry's message is reportedly "noisy," return early. + return + } + } + imp.testHelper() for _, appender := range imp.appenders { err := appender.Write(entry.Entry, entry.Fields) diff --git a/logging/logging.go b/logging/logging.go index 9bfe231d5c6..0f7f1671d77 100644 --- a/logging/logging.go +++ b/logging/logging.go @@ -2,8 +2,10 @@ package logging import ( + "os" "sync" "testing" + "time" "go.uber.org/zap" "go.uber.org/zap/zapcore" @@ -11,6 +13,8 @@ import ( "go.viam.com/utils" ) +const dedupNoisyLogsEnvVar = "VIAM_DEDUP_LOGS" + var ( globalMu sync.RWMutex globalLogger = NewDebugLogger("global") @@ -18,8 +22,19 @@ var ( // GlobalLogLevel should be used whenever a zap logger is created that wants to obey the debug // flag from the CLI or robot config. GlobalLogLevel = zap.NewAtomicLevelAt(zap.InfoLevel) + + // Whether to de-duplicate noisy logs; obtained from value of + // `dedupNoisyLogsEnvVar` and defaults to true. Export env var to "false" to + // turn off de-duplicating logic. + dedupNoisyLogs = false ) +func init() { + if dedupNoisyLogEnvVal := os.Getenv(dedupNoisyLogsEnvVar); dedupNoisyLogEnvVal == "false" { + dedupNoisyLogs = false + } +} + // ReplaceGlobal replaces the global loggers. func ReplaceGlobal(logger Logger) { globalMu.Lock() @@ -62,11 +77,15 @@ func NewZapLoggerConfig() zap.Config { // NewLogger returns a new logger that outputs Info+ logs to stdout in UTC. func NewLogger(name string) Logger { logger := &impl{ - name: name, - level: NewAtomicLevelAt(INFO), - appenders: []Appender{NewStdoutAppender()}, - registry: newRegistry(), - testHelper: func() {}, + name: name, + level: NewAtomicLevelAt(INFO), + appenders: []Appender{NewStdoutAppender()}, + registry: newRegistry(), + testHelper: func() {}, + dedupNoisyLogs: dedupNoisyLogs, + recentMessageCounts: make(map[string]int), + recentMessageEntries: make(map[string]LogEntry), + recentMessageWindowStart: time.Now(), } logger.registry.registerLogger(name, logger) @@ -78,11 +97,15 @@ func NewLogger(name string) Logger { func NewLoggerWithRegistry(name string) (Logger, *Registry) { reg := newRegistry() logger := &impl{ - name: name, - level: NewAtomicLevelAt(INFO), - appenders: []Appender{NewStdoutAppender()}, - registry: reg, - testHelper: func() {}, + name: name, + level: NewAtomicLevelAt(INFO), + appenders: []Appender{NewStdoutAppender()}, + registry: reg, + testHelper: func() {}, + dedupNoisyLogs: dedupNoisyLogs, + recentMessageCounts: make(map[string]int), + recentMessageEntries: make(map[string]LogEntry), + recentMessageWindowStart: time.Now(), } logger.registry.registerLogger(name, logger) @@ -92,11 +115,15 @@ func NewLoggerWithRegistry(name string) (Logger, *Registry) { // NewDebugLogger returns a new logger that outputs Debug+ logs to stdout in UTC. func NewDebugLogger(name string) Logger { logger := &impl{ - name: name, - level: NewAtomicLevelAt(DEBUG), - appenders: []Appender{NewStdoutAppender()}, - registry: newRegistry(), - testHelper: func() {}, + name: name, + level: NewAtomicLevelAt(DEBUG), + appenders: []Appender{NewStdoutAppender()}, + registry: newRegistry(), + testHelper: func() {}, + dedupNoisyLogs: dedupNoisyLogs, + recentMessageCounts: make(map[string]int), + recentMessageEntries: make(map[string]LogEntry), + recentMessageWindowStart: time.Now(), } logger.registry.registerLogger(name, logger) @@ -107,11 +134,15 @@ func NewDebugLogger(name string) Logger { // pre-existing appenders/outputs. func NewBlankLogger(name string) Logger { logger := &impl{ - name: name, - level: NewAtomicLevelAt(DEBUG), - appenders: []Appender{}, - registry: newRegistry(), - testHelper: func() {}, + name: name, + level: NewAtomicLevelAt(DEBUG), + appenders: []Appender{}, + registry: newRegistry(), + testHelper: func() {}, + dedupNoisyLogs: dedupNoisyLogs, + recentMessageCounts: make(map[string]int), + recentMessageEntries: make(map[string]LogEntry), + recentMessageWindowStart: time.Now(), } logger.registry.registerLogger(name, logger) @@ -136,6 +167,8 @@ func NewObservedTestLogger(tb testing.TB) (Logger, *observer.ObservedLogs) { }, registry: newRegistry(), testHelper: tb.Helper, + // Only prod loggers should de-duplicate noisy logs. + dedupNoisyLogs: false, } return logger, observedLogs @@ -155,6 +188,8 @@ func NewObservedTestLoggerWithRegistry(tb testing.TB, name string) (Logger, *obs }, registry: registry, testHelper: tb.Helper, + // Only prod loggers should de-duplicate noisy logs. + dedupNoisyLogs: false, } return logger, observedLogs, registry @@ -189,6 +224,8 @@ func NewInMemoryLogger(tb testing.TB) *MemLogger { }, registry: newRegistry(), testHelper: tb.Helper, + // Only prod loggers should de-duplicate noisy logs. + dedupNoisyLogs: false, } memLogger := &MemLogger{logger, tb, observedLogs} From f360807c4dd7fd87687a812f9eacb12549930d84 Mon Sep 17 00:00:00 2001 From: Benji Rewis Date: Mon, 18 Nov 2024 16:32:31 -0500 Subject: [PATCH 2/3] typo --- logging/logging.go | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) diff --git a/logging/logging.go b/logging/logging.go index 0f7f1671d77..3defe2fa41c 100644 --- a/logging/logging.go +++ b/logging/logging.go @@ -13,6 +13,9 @@ import ( "go.viam.com/utils" ) +// Environment variable to control whether noisy logs are de-deduplicated. Set +// to "false" to turn off de-duplicating logic; de-duplication logic is enabled +// by default. const dedupNoisyLogsEnvVar = "VIAM_DEDUP_LOGS" var ( @@ -26,7 +29,7 @@ var ( // Whether to de-duplicate noisy logs; obtained from value of // `dedupNoisyLogsEnvVar` and defaults to true. Export env var to "false" to // turn off de-duplicating logic. - dedupNoisyLogs = false + dedupNoisyLogs = true ) func init() { From 76960728fc6ab6847e0c34224908a947cad8ad3b Mon Sep 17 00:00:00 2001 From: Benji Rewis Date: Tue, 19 Nov 2024 15:38:14 -0500 Subject: [PATCH 3/3] up window --- logging/impl.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/logging/impl.go b/logging/impl.go index 41ee35803ee..da6a8c24734 100644 --- a/logging/impl.go +++ b/logging/impl.go @@ -17,7 +17,7 @@ import ( const ( // Window duration over which to consider log messages "noisy." - noisyMessageWindowDuration = 5 * time.Second + noisyMessageWindowDuration = 10 * time.Second // Count threshold within `noisyMessageWindowDuration` after which to // consider log messages "noisy." noisyMessageCountThreshold = 3