-
Notifications
You must be signed in to change notification settings - Fork 129
RSDK-13826: Do not deduplicate for debug-level loggers (or when debug is on) #5964
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
base: main
Are you sure you want to change the base?
Changes from all commits
File filter
Filter by extension
Conversations
Jump to
Diff view
Diff view
There are no files selected for viewing
| Original file line number | Diff line number | Diff line change |
|---|---|---|
|
|
@@ -263,7 +263,11 @@ func (imp *impl) shouldLog(logLevel Level) bool { | |
| } | ||
|
|
||
| func (imp *impl) Write(entry *LogEntry) { | ||
| if imp.registry.DeduplicateLogs.Load() && !imp.neverDeduplicate { | ||
| if imp.registry.DeduplicateLogs.Load() && !imp.neverDeduplicate && | ||
| // If the logger is at DEBUG level, or viam-server is run with "debug": true or | ||
| // `-debug`, never deduplicate. If a user asks for debug logs, they likely want to see | ||
| // all logs. | ||
| imp.level.Get() != DEBUG && GlobalLogLevel.Level() != zapcore.DebugLevel { | ||
|
Comment on lines
+266
to
+270
Member
Author
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Thanks Copilot. |
||
| hashkeyedEntry := entry.HashKey() | ||
|
|
||
| // If we have entered a new recentMessage window, output noisy logs from | ||
|
|
||
| Original file line number | Diff line number | Diff line change |
|---|---|---|
|
|
@@ -502,7 +502,7 @@ func TestLoggingDeduplication(t *testing.T) { | |
| notStdout := &bytes.Buffer{} | ||
| logger := &impl{ | ||
| name: "impl", | ||
| level: NewAtomicLevelAt(DEBUG), | ||
| level: NewAtomicLevelAt(INFO), | ||
|
Member
Author
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Needs to be |
||
| appenders: []Appender{NewWriterAppender(notStdout)}, | ||
| registry: registry, | ||
| testHelper: func() {}, | ||
|
|
@@ -608,6 +608,100 @@ func TestLoggingDeduplication(t *testing.T) { | |
| `2023-10-30T13:19:45.806Z INFO impl logging/impl_test.go:132 foo {"key":"value"}`) | ||
| } | ||
|
|
||
| func TestDebugLevelNeverDeduplicates(t *testing.T) { | ||
| // Create a logger object that will write to the `notStdout` buffer. Explicitly | ||
| // set DeduplicateLogs to true on the registry for the logger. | ||
| registry := newRegistry() | ||
| registry.DeduplicateLogs.Store(true) | ||
|
|
||
| originalNoisyMessageWindowDuration := noisyMessageWindowDuration | ||
| noisyMessageWindowDuration = 500 * time.Millisecond | ||
| defer func() { | ||
| noisyMessageWindowDuration = originalNoisyMessageWindowDuration | ||
| }() | ||
|
|
||
| // A logger at DEBUG level should never deduplicate, even without NeverDeduplicate(). | ||
| notStdout := &bytes.Buffer{} | ||
| logger := &impl{ | ||
| name: "impl", | ||
| level: NewAtomicLevelAt(DEBUG), | ||
| appenders: []Appender{NewWriterAppender(notStdout)}, | ||
| registry: registry, | ||
| testHelper: func() {}, | ||
| recentMessageCounts: make(map[string]int), | ||
| recentMessageEntries: make(map[string]LogEntry), | ||
| recentMessageWindowStart: time.Now(), | ||
| } | ||
|
|
||
| for range 4 { | ||
| logger.Info("identical message") | ||
|
Member
Author
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Note that an Info, Warn, or Error (in addition to Debug) log from a logger with a level set to "debug" will not be deduplicated. E.g., if I set the builtin datamanager's log level to "debug", logs of all levels from that logger will not be deduplicated. |
||
| assertLogMatches(t, notStdout, | ||
| `2023-10-30T13:19:45.806Z INFO impl logging/impl_test.go:132 identical message`) | ||
| } | ||
|
|
||
| // Bumping to INFO should re-enable deduplication. | ||
| logger.SetLevel(INFO) | ||
| for range 4 { | ||
| logger.Info("identical message") | ||
| } | ||
| // Only the first three (up to noisyMessageCountThreshold) should appear. | ||
| for range noisyMessageCountThreshold { | ||
| assertLogMatches(t, notStdout, | ||
| `2023-10-30T13:19:45.806Z INFO impl logging/impl_test.go:132 identical message`) | ||
| } | ||
| test.That(t, notStdout.Len(), test.ShouldEqual, 0) | ||
| } | ||
|
|
||
| func TestGlobalDebugLevelNeverDeduplicates(t *testing.T) { | ||
| // Create a logger object that will write to the `notStdout` buffer. Explicitly | ||
| // set DeduplicateLogs to true on the registry for the logger. | ||
| registry := newRegistry() | ||
| registry.DeduplicateLogs.Store(true) | ||
|
|
||
| originalNoisyMessageWindowDuration := noisyMessageWindowDuration | ||
| noisyMessageWindowDuration = 500 * time.Millisecond | ||
| defer func() { | ||
| noisyMessageWindowDuration = originalNoisyMessageWindowDuration | ||
| }() | ||
|
|
||
| // Set GlobalLogLevel to DEBUG, and restore it after the test. | ||
| originalGlobalLogLevel := GlobalLogLevel.Level() | ||
| GlobalLogLevel.SetLevel(zapcore.DebugLevel) | ||
| defer GlobalLogLevel.SetLevel(originalGlobalLogLevel) | ||
|
|
||
| // Logger itself is at INFO level — deduplication should still be suppressed because | ||
| // the global debug flag is on. | ||
| notStdout := &bytes.Buffer{} | ||
| logger := &impl{ | ||
| name: "impl", | ||
| level: NewAtomicLevelAt(INFO), | ||
| appenders: []Appender{NewWriterAppender(notStdout)}, | ||
| registry: registry, | ||
| testHelper: func() {}, | ||
| recentMessageCounts: make(map[string]int), | ||
| recentMessageEntries: make(map[string]LogEntry), | ||
| recentMessageWindowStart: time.Now(), | ||
| } | ||
|
|
||
| for range 4 { | ||
| logger.Info("identical message") | ||
| assertLogMatches(t, notStdout, | ||
| `2023-10-30T13:19:45.806Z INFO impl logging/impl_test.go:132 identical message`) | ||
| } | ||
|
|
||
| // Restoring GlobalLogLevel to a non-debug level should re-enable deduplication. | ||
| GlobalLogLevel.SetLevel(zapcore.InfoLevel) | ||
| for range 4 { | ||
| logger.Info("identical message") | ||
| } | ||
| // Only the first three (up to noisyMessageCountThreshold) should appear. | ||
| for range noisyMessageCountThreshold { | ||
| assertLogMatches(t, notStdout, | ||
| `2023-10-30T13:19:45.806Z INFO impl logging/impl_test.go:132 identical message`) | ||
| } | ||
| test.That(t, notStdout.Len(), test.ShouldEqual, 0) | ||
| } | ||
|
|
||
| func TestNeverDeduplicate(t *testing.T) { | ||
| // Create a logger object that will write to the `notStdout` buffer. Explicitly | ||
| // set `DeduplicateLogs` to true on the registry for the logger. | ||
|
|
||
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Setting
"debug": trueor running with-debugis now equivalent to putting"disable_log_deduplication": truein your JSON config.