RSDK-10186 Exclude stack traces from log deduplication

[benjirewis]

Avoids deduplicating logs whose logger names end with StdErr or StdOut. Adds tests for that behavior.

Tested that module stack traces are not deduplicated manually.

[benjirewis]

This is... hacky. I'd rather call something like SetDeduplicateLogs(false) on the loggers that actually output to STDOUT and STDERR for managed processes/modules. Two issues though:

• DeduplicateLogs is a value on the registry and setting it would affect all parent loggers of the aforementioned ones
• Exposing SetDeduplicateLogs is difficult at that point in goutils; we do not have access to the logger registry object, and adding methods to logging interfaces is... annoying (something-something-zap-compability)

Still happy to discuss other solutions than the one I've implemented here.

[dgottlieb]

DeduplicateLogs is a value on the registry and setting it would affect all parent loggers of the aforementioned ones

Just sharing the thought of how that would be done:

diff --git a/logging/impl.go b/logging/impl.go
index e5ef5c655..65d494da8 100644
--- a/logging/impl.go
+++ b/logging/impl.go
@@ -26,8 +26,9 @@ var (
 
 type (
        impl struct {
-               name  string
-               level AtomicLevel
+               name            string
+               level           AtomicLevel
+               deduplicateLogs bool
 
                appenders []Appender
                registry  *Registry
@@ -124,6 +125,7 @@ func (imp *impl) Sublogger(subname string) Logger {
        sublogger := &impl{
                newName,
                NewAtomicLevelAt(imp.level.Get()),
+               imp.deduplicateLogs,
                imp.appenders,
                imp.registry,
                imp.testHelper,
@@ -141,6 +143,10 @@ func (imp *impl) Sublogger(subname string) Logger {
        return imp.registry.getOrRegister(newName, sublogger)
 }
 
+func (imp *impl) SetDeduplcateLogs(val bool) {
+       imp.deduplicateLogs = val
+}
+
 func (imp *impl) Named(name string) *zap.SugaredLogger {
        return imp.AsZap().Named(name)
 }
@@ -245,7 +251,7 @@ func (imp *impl) shouldLog(logLevel Level) bool {
 }
 
 func (imp *impl) Write(entry *LogEntry) {
-       if imp.registry.DeduplicateLogs.Load() {
+       if imp.deduplicateLogs {
                hashkeyedEntry := entry.HashKey()
 
                // If we have entered a new recentMessage window, output noisy logs from
diff --git a/logging/logger.go b/logging/logger.go
index 810f81ae9..8fe639a42 100644
--- a/logging/logger.go
+++ b/logging/logger.go
@@ -16,6 +16,7 @@ type Logger interface {
        SetLevel(level Level)
        GetLevel() Level
        Sublogger(subname string) Logger
+       SetDeduplcateLogs(val bool)
        AddAppender(appender Appender)
        AsZap() *zap.SugaredLogger
        // Unconditionally logs a LogEntry object. Specifically any configured log level is ignored.
diff --git a/logging/logging.go b/logging/logging.go
index 7cec6a167..20fe6eb93 100644
--- a/logging/logging.go
+++ b/logging/logging.go
@@ -85,6 +85,7 @@ func NewLoggerWithRegistry(name string) (Logger, *Registry) {
                name:                     name,
                level:                    NewAtomicLevelAt(INFO),
                appenders:                []Appender{NewStdoutAppender()},
+               deduplicateLogs:          reg.DeduplicateLogs.Load(),
                registry:                 reg,
                testHelper:               func() {},
                recentMessageCounts:      make(map[string]int),

Though there would be some more New*Logger constructors to modify.

Exposing SetDeduplicateLogs is difficult at that point in goutils; we do not have access to the logger registry object, and adding methods to logging interfaces is... annoying (something-something-zap-compability)

Yeah, I'd definitely avoid exposing some "SetDeduplicateLogs" function in goutils -- that's a good catch.

Without pasting the goutils half of this change, we could try something like this:

diff --git a/module/modmanager/manager.go b/module/modmanager/manager.go
index 294ec3f04..6d0ca209f 100644
--- a/module/modmanager/manager.go
+++ b/module/modmanager/manager.go
@@ -1207,7 +1207,11 @@ func (m *module) startProcess(
                pconf.Args = append(pconf.Args, fmt.Sprintf(logLevelArgumentTemplate, "debug"))
        }
 
-       m.process = pexec.NewManagedProcess(pconf, m.logger)
+       stdoutLogger := m.logger.Sublogger("stdout")
+       stdoutLogger.SetDeduplicateLogs(false)
+       stderrLogger := m.logger.Sublogger("stderr")
+       stderrLogger.SetDeduplicateLogs(false)
+       m.process = pexec.NewManagedProcess(pconf, m.logger, stdoutLogger, stderrLogger)
 
        if err := m.process.Start(context.Background()); err != nil {
                return errors.WithMessage(err, "module startup failed")

@benjirewis already noted that could break agent usages calls (when they upgrade). But hiding these loggers as optional arguments inside of pconf would also work.

[benjirewis]

Gotcha yeah I get the concept on both points I think... I have a slight preference for your solution. My current solution will quietly turn off log deduplication for any logger that happens to (I realize an odd case) end with StdOut or StdErr.

already noted that could break agent usages

Also, I was actually wrong there: agent does not use NewManagedProcess to start viam-server, it uses exec.Command to call the binary directly.

Will work on your version and re-request review. Will have to do a goutils PR and may discover that the path you're suggesting here is actually not as "better" as we thought. Thanks!

[benjirewis]

Been trying to implement this. I don't think it's impossible, but I'm having trouble making it "elegant."

The issue with your patch there is that instantiation of the logger just sets imp.deduplicateLogs: reg.DeduplicateLogs.Load(). What happens if there's a later reg.DeduplicateLogs.Store(newVal) due to reconfiguration (we also rely on calling Store after NewLoggerWithRegistry in the web server entrypoint code)?

Basically, we need all loggers to look to the global (on the registry) DeduplicateLogs value that can change at any point, but we want some loggers (the module stdout and stderr loggers) to override whatever DeduplicateLogs is and never deduplicate. Again, it's technically feasible, but I think impl needs something like a deduplicateLogsOverride *bool value. Or, if we only want some loggers to be able to turn off deduping, something like SetNeverDeduplicate().

Just slightly more complicated (especially given passing in STDOUT and STDERR loggers to goutils even when we already pass in a regular logger) and makes touching this code in the future not as fun. That's pushing me a bit toward this simpler suffix solution.

[dgottlieb]

Ah good find -- my bad.

Or, if we only want some loggers to be able to turn off deduping, something like SetNeverDeduplicate().

Yeah, I think that will be sufficient for what we need to express:

if registry.Deduplicate.Load() && imp.DoNotDeduplicateOverride {
...
}

[benjirewis]

Nice; went for the NeverDeduplicate() method along with some goutils changes. Let me know what you think.

[dgottlieb]

I'm also ok with this change as advertised