From db6d54d8d3f8ba5d3aa40ebce69bd8061d389e67 Mon Sep 17 00:00:00 2001 From: Dennis Lanov Date: Wed, 12 Aug 2026 11:45:00 -0500 Subject: [PATCH] fix(cli): keep dirctl logs off stdout Signed-off-by: Dennis Lanov --- cli/cli.go | 8 + cli/cmd/daemon/start.go | 5 + utils/logging/config.go | 8 + utils/logging/config_test.go | 35 ++++ utils/logging/logging.go | 117 +++++++++++-- utils/logging/logging_test.go | 321 +++++++++++++++++++++++++++++++--- 6 files changed, 456 insertions(+), 38 deletions(-) diff --git a/cli/cli.go b/cli/cli.go index 75c67f68b..07ef22e98 100644 --- a/cli/cli.go +++ b/cli/cli.go @@ -10,9 +10,17 @@ import ( "syscall" "github.com/agntcy/dir/cli/cmd" + "github.com/agntcy/dir/utils/logging" ) func main() { + // dirctl's result output is machine-readable (stdout is often piped into + // jq, parsed as JSON, etc.), so diagnostic logs default to stderr instead + // of the package-wide stdout default used by server/reconciler binaries. + // An explicit DIRECTORY_LOGGER_LOG_FILE or DIRECTORY_LOGGER_LOG_STREAM + // still wins over this (see utils/logging.SetDefaultOutput). + logging.SetDefaultOutput(os.Stderr) + ctx, cancel := signal.NotifyContext(context.Background(), os.Interrupt, syscall.SIGHUP, syscall.SIGTERM) if err := cmd.Run(ctx); err != nil { diff --git a/cli/cmd/daemon/start.go b/cli/cmd/daemon/start.go index ae05f68a7..6d8d8e6a0 100644 --- a/cli/cmd/daemon/start.go +++ b/cli/cmd/daemon/start.go @@ -41,6 +41,11 @@ The daemon blocks until SIGINT or SIGTERM is received.`, //nolint:cyclop func runStart(cmd *cobra.Command, _ []string) error { + // `daemon start` bundles the apiserver and reconciler in-process, so it + // keeps their stdout logging behavior rather than the stderr default + // cli.go sets for normal dirctl commands. + logging.SetDefaultOutput(os.Stdout) + running, pid, err := readPID() if err != nil { return err diff --git a/utils/logging/config.go b/utils/logging/config.go index 20e346367..7554f9599 100644 --- a/utils/logging/config.go +++ b/utils/logging/config.go @@ -21,6 +21,10 @@ type Config struct { LogFile string `json:"log_file,omitempty" mapstructure:"log_file"` LogLevel string `json:"log_level,omitempty" mapstructure:"log_level"` LogFormat string `json:"log_format,omitempty" mapstructure:"log_format"` + // LogStream explicitly selects "stdout" or "stderr". Left empty, it means + // "use the binary's default" - deliberately has no Viper default, since + // that default differs per binary (see SetDefaultOutput). + LogStream string `json:"log_stream,omitempty" mapstructure:"log_stream"` } func LoadConfig() (*Config, error) { @@ -41,6 +45,10 @@ func LoadConfig() (*Config, error) { _ = v.BindEnv("log_format") v.SetDefault("log_format", DefaultLogFormat) + // No default: an unset log_stream means "use the binary's default", + // which InitLogger/SetDefaultOutput resolve per binary. + _ = v.BindEnv("log_stream") + // Load configuration into struct decodeHooks := mapstructure.ComposeDecodeHookFunc( mapstructure.TextUnmarshallerHookFunc(), diff --git a/utils/logging/config_test.go b/utils/logging/config_test.go index 87364436a..dced8d03e 100644 --- a/utils/logging/config_test.go +++ b/utils/logging/config_test.go @@ -14,6 +14,7 @@ func TestLoadConfigWithDefaults(t *testing.T) { os.Unsetenv("DIRECTORY_LOGGER_LOG_FILE") os.Unsetenv("DIRECTORY_LOGGER_LOG_LEVEL") os.Unsetenv("DIRECTORY_LOGGER_LOG_FORMAT") + os.Unsetenv("DIRECTORY_LOGGER_LOG_STREAM") cfg, err := LoadConfig() if err != nil { @@ -32,6 +33,30 @@ func TestLoadConfigWithDefaults(t *testing.T) { if cfg.LogFile != "" { t.Errorf("Expected LogFile='', got: %s", cfg.LogFile) } + + if cfg.LogStream != "" { + t.Errorf("Expected LogStream='' (use binary default), got: %s", cfg.LogStream) + } +} + +// TestLoadConfigLogStreamValues verifies DIRECTORY_LOGGER_LOG_STREAM loads through +// unchanged for each supported value (unset stays empty - see TestLoadConfigWithDefaults +// for why that matters). +func TestLoadConfigLogStreamValues(t *testing.T) { + for _, stream := range []string{"stdout", "stderr"} { + t.Run(stream, func(t *testing.T) { + t.Setenv("DIRECTORY_LOGGER_LOG_STREAM", stream) + + cfg, err := LoadConfig() + if err != nil { + t.Fatalf("LoadConfig() failed: %v", err) + } + + if cfg.LogStream != stream { + t.Errorf("Expected LogStream=%s, got: %s", stream, cfg.LogStream) + } + }) + } } // TestLoadConfigWithEnvVars verifies environment variable configuration. @@ -40,6 +65,7 @@ func TestLoadConfigWithEnvVars(t *testing.T) { t.Setenv("DIRECTORY_LOGGER_LOG_FILE", "/tmp/test.log") t.Setenv("DIRECTORY_LOGGER_LOG_LEVEL", "DEBUG") t.Setenv("DIRECTORY_LOGGER_LOG_FORMAT", "json") + t.Setenv("DIRECTORY_LOGGER_LOG_STREAM", "stderr") cfg, err := LoadConfig() if err != nil { @@ -58,6 +84,10 @@ func TestLoadConfigWithEnvVars(t *testing.T) { if cfg.LogFormat != "json" { t.Errorf("Expected LogFormat='json', got: %s", cfg.LogFormat) } + + if cfg.LogStream != "stderr" { + t.Errorf("Expected LogStream='stderr', got: %s", cfg.LogStream) + } } // TestLoadConfigWithPartialEnvVars verifies partial environment variable configuration. @@ -157,6 +187,7 @@ func TestConfigJSONMarshaling(t *testing.T) { LogFile: "/var/log/app.log", LogLevel: "INFO", LogFormat: "json", + LogStream: "stdout", } // Just verify the struct is valid and fields are accessible @@ -171,6 +202,10 @@ func TestConfigJSONMarshaling(t *testing.T) { if cfg.LogFormat != "json" { t.Errorf("LogFormat mismatch") } + + if cfg.LogStream != "stdout" { + t.Errorf("LogStream mismatch") + } } // TestConfigConstants verifies all constants are correctly defined. diff --git a/utils/logging/logging.go b/utils/logging/logging.go index b2a1c175f..d5bec8ba5 100644 --- a/utils/logging/logging.go +++ b/utils/logging/logging.go @@ -4,6 +4,7 @@ package logging import ( + "io" "log/slog" "os" "strings" @@ -16,23 +17,102 @@ const ( // Log format types. formatJSON = "json" formatText = "text" + + // Log stream types. + streamStdout = "stdout" + streamStderr = "stderr" ) var once sync.Once -// getLogOutput determines where logs should be written. -func getLogOutput(logFilePath string) *os.File { - if logFilePath != "" { - // Try to open or create the log file. - file, err := os.OpenFile(logFilePath, os.O_APPEND|os.O_CREATE|os.O_WRONLY, filePermission) - if err == nil { - return file - } +// switchableWriter is an io.Writer whose target can be swapped after +// construction. slog handlers bind to a writer once, at construction time - +// including the ~60 `var logger = logging.Logger(component)` package-level +// loggers in this repo, all constructed before any binary's main() runs. +// Routing writes through a switchableWriter lets SetDefaultOutput redirect +// those already-constructed loggers later, without a custom slog.Handler. +type switchableWriter struct { + mu sync.RWMutex + w io.Writer +} + +func newSwitchableWriter(w io.Writer) *switchableWriter { + return &switchableWriter{w: w} +} + +func (s *switchableWriter) Write(p []byte) (int, error) { + s.mu.RLock() + defer s.mu.RUnlock() + + //nolint:wrapcheck // io.Writer implementations pass through the underlying error unwrapped. + return s.w.Write(p) +} + +func (s *switchableWriter) Set(w io.Writer) { + s.mu.Lock() + defer s.mu.Unlock() + + s.w = w +} + +// defaultWriter is the process-wide fallback output target, used only when +// InitLogger did not bind the handler to an explicit log file or an explicit +// DIRECTORY_LOGGER_LOG_STREAM. Binaries pick their own default via +// SetDefaultOutput. +var defaultWriter = newSwitchableWriter(os.Stdout) + +// getFileOutput attempts to open the configured log file. It returns nil if +// no file is configured, or if opening it fails - the failure is logged so +// the caller can fall back to the next output in the precedence order. +func getFileOutput(logFilePath string) *os.File { + if logFilePath == "" { + return nil + } + + file, err := os.OpenFile(logFilePath, os.O_APPEND|os.O_CREATE|os.O_WRONLY, filePermission) + if err != nil { + slog.Error("Failed to open log file, falling back", "error", err) + + return nil + } + + return file +} + +// resolveExplicitStream returns the writer for an explicit +// DIRECTORY_LOGGER_LOG_STREAM value. ok is false when the stream is unset or +// invalid, meaning the caller should fall back to the binary-default writer. +func resolveExplicitStream(logStream string) (io.Writer, bool) { + switch strings.ToLower(strings.TrimSpace(logStream)) { + case "": + return nil, false + case streamStdout: + return os.Stdout, true + case streamStderr: + return os.Stderr, true + default: + slog.Warn("Invalid log stream, using default output", "log_stream", logStream) + + return nil, false + } +} + +// resolveOutput implements the output-selection precedence required by +// #2009: +// 1. An explicit log file that opens successfully always wins. +// 2. Otherwise an explicit LogStream (stdout/stderr) wins. +// 3. Otherwise logs flow through defaultWriter, which the binary can +// redirect later via SetDefaultOutput. +func resolveOutput(cfg *Config) io.Writer { + if file := getFileOutput(cfg.LogFile); file != nil { + return file + } - slog.Error("Failed to open log file, defaulting to stdout", "error", err) + if w, ok := resolveExplicitStream(cfg.LogStream); ok { + return w } - return os.Stdout + return defaultWriter } // InitLogger initializes the global logger with the provided configuration. @@ -42,8 +122,6 @@ func InitLogger(cfg *Config) { once.Do(func() { var logLevel slog.Level - logOutput := getLogOutput(cfg.LogFile) - // Parse log level; default to INFO if invalid. if err := logLevel.UnmarshalText([]byte(strings.ToLower(cfg.LogLevel))); err != nil { slog.Warn("Invalid log level, defaulting to INFO", "error", err) @@ -51,6 +129,8 @@ func InitLogger(cfg *Config) { logLevel = slog.LevelInfo } + output := resolveOutput(cfg) + // Create handler based on format var handler slog.Handler @@ -58,13 +138,13 @@ func InitLogger(cfg *Config) { switch strings.ToLower(cfg.LogFormat) { case formatJSON: - handler = slog.NewJSONHandler(logOutput, opts) + handler = slog.NewJSONHandler(output, opts) case formatText: - handler = slog.NewTextHandler(logOutput, opts) + handler = slog.NewTextHandler(output, opts) default: slog.Warn("Invalid log format, defaulting to text", "format", cfg.LogFormat) - handler = slog.NewTextHandler(logOutput, opts) + handler = slog.NewTextHandler(output, opts) } // Set global logger before other packages initialize. @@ -72,6 +152,13 @@ func InitLogger(cfg *Config) { }) } +// SetDefaultOutput redirects defaultWriter (see above). It has no effect on +// loggers bound to an explicit log file or DIRECTORY_LOGGER_LOG_STREAM, since +// those write directly to their configured target instead. +func SetDefaultOutput(w io.Writer) { + defaultWriter.Set(w) +} + func Logger(component string) *slog.Logger { return slog.Default().With("component", component) } diff --git a/utils/logging/logging_test.go b/utils/logging/logging_test.go index 8a7a683ea..a275964c2 100644 --- a/utils/logging/logging_test.go +++ b/utils/logging/logging_test.go @@ -6,9 +6,11 @@ package logging import ( "bytes" "encoding/json" + "io" "log/slog" "os" "strings" + "sync" "testing" ) @@ -222,6 +224,7 @@ func TestConfigStruct(t *testing.T) { LogFile: "/tmp/test.log", LogLevel: "DEBUG", LogFormat: testLogFormat, + LogStream: "stderr", } if cfg.LogFile != "/tmp/test.log" { @@ -232,6 +235,10 @@ func TestConfigStruct(t *testing.T) { t.Errorf("Expected LogLevel='DEBUG', got: %s", cfg.LogLevel) } + if cfg.LogStream != "stderr" { + t.Errorf("Expected LogStream='stderr', got: %s", cfg.LogStream) + } + if cfg.LogFormat != testLogFormat { t.Errorf("Expected LogFormat='%s', got: %s", testLogFormat, cfg.LogFormat) } @@ -286,42 +293,310 @@ func TestJSONHandlerMultipleMessages(t *testing.T) { } } -// TestGetLogOutputStdout verifies getLogOutput returns stdout for empty path. -func TestGetLogOutputStdout(t *testing.T) { - output := getLogOutput("") - if output != os.Stdout { - t.Error("Expected stdout for empty path") +// TestGetFileOutput verifies getFileOutput returns nil when no file is configured or the +// path can't be opened, and a writable handle for a valid path. +func TestGetFileOutput(t *testing.T) { + validPath := t.TempDir() + "/test.log" + + tests := []struct { + name string + path string + wantNil bool + }{ + {"empty path", "", true}, + {"invalid path", "/invalid/directory/that/does/not/exist/test.log", true}, + {"valid path", validPath, false}, + } + + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + output := getFileOutput(tt.path) + + if tt.wantNil { + if output != nil { + t.Errorf("Expected nil, got: %v", output) + } + + return + } + + if output == nil { + t.Fatal("Expected a file handle, got nil") + } + + defer output.Close() + + if _, err := output.WriteString("test"); err != nil { + t.Errorf("Failed to write to log file: %v", err) + } + }) + } +} + +// TestResolveExplicitStream verifies stdout/stderr selection, case-insensitively, and +// that unset/invalid values report ok=false so the caller falls back to the default writer. +func TestResolveExplicitStream(t *testing.T) { + tests := []struct { + name string + logStream string + wantOK bool + want io.Writer + }{ + {"empty", "", false, nil}, + {"stdout lowercase", "stdout", true, os.Stdout}, + {"stdout uppercase", "STDOUT", true, os.Stdout}, + {"stdout mixed case with spaces", " StdOut ", true, os.Stdout}, + {"stderr lowercase", "stderr", true, os.Stderr}, + {"stderr uppercase", "STDERR", true, os.Stderr}, + {"invalid", "bogus", false, nil}, + } + + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + w, ok := resolveExplicitStream(tt.logStream) + if ok != tt.wantOK { + t.Errorf("Expected ok=%v, got: %v", tt.wantOK, ok) + } + + if ok && w != tt.want { + t.Errorf("Expected writer=%v, got: %v", tt.want, w) + } + }) } } -// TestGetLogOutputInvalidPath verifies getLogOutput falls back to stdout for invalid path. -func TestGetLogOutputInvalidPath(t *testing.T) { - // Use an invalid path (directory that doesn't exist) - output := getLogOutput("/invalid/directory/that/does/not/exist/test.log") - if output != os.Stdout { - t.Error("Expected stdout fallback for invalid path") +// TestResolveOutputPrecedence verifies the #2009 output-selection precedence end to end: +// a successfully-opened LogFile beats an explicit LogStream, which beats the switchable +// defaultWriter, and both an invalid file and an invalid stream fall through to the next +// tier rather than a hardcoded choice. +func TestResolveOutputPrecedence(t *testing.T) { + const invalidFile = "/invalid/directory/that/does/not/exist/test.log" + + validFile := t.TempDir() + "/test.log" + + tests := []struct { + name string + logFile string + logStream string + want io.Writer // nil means "expect a file handle for the configured LogFile" + }{ + {"no file, no stream -> default writer", "", "", defaultWriter}, + {"no file, stream=stdout -> stdout", "", "stdout", os.Stdout}, + {"no file, stream=stderr -> stderr", "", "stderr", os.Stderr}, + {"no file, invalid stream -> default writer", "", "bogus", defaultWriter}, + {"invalid file, no stream -> default writer", invalidFile, "", defaultWriter}, + {"invalid file, stream=stdout -> stdout", invalidFile, "stdout", os.Stdout}, + {"invalid file, stream=stderr -> stderr", invalidFile, "stderr", os.Stderr}, + {"valid file, stream=stderr -> file wins", validFile, "stderr", nil}, + } + + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + cfg := &Config{ + LogFile: tt.logFile, + LogStream: tt.logStream, + } + + output := resolveOutput(cfg) + + if tt.want != nil { + if output != tt.want { + t.Errorf("Expected %v, got: %v", tt.want, output) + } + + return + } + + file, ok := output.(*os.File) + if !ok { + t.Fatalf("Expected *os.File, got: %T", output) + } + + defer file.Close() + + if file.Name() != cfg.LogFile { + t.Errorf("Expected file %s, got: %s", cfg.LogFile, file.Name()) + } + }) } } -// TestGetLogOutputValidPath verifies getLogOutput can create a log file. -func TestGetLogOutputValidPath(t *testing.T) { - // Create a temporary file +// TestExplicitOutputImmuneToSetDefaultOutput proves requirements D, E and F directly: +// once resolveOutput selects an explicit LogFile or LogStream, a later SetDefaultOutput +// call must never change what it resolves to - only the unset-file/unset-stream fallback +// (defaultWriter) is redirectable. +func TestExplicitOutputImmuneToSetDefaultOutput(t *testing.T) { + t.Cleanup(func() { defaultWriter.Set(os.Stdout) }) + tmpFile := t.TempDir() + "/test.log" - output := getLogOutput(tmpFile) - if output == os.Stdout { - t.Error("Expected file handle, got stdout") + tests := []struct { + name string + cfg *Config + want io.Writer // nil means "expect a file handle for cfg.LogFile" + }{ + {"explicit stdout survives SetDefaultOutput", &Config{LogStream: "stdout"}, os.Stdout}, + {"explicit stderr survives SetDefaultOutput", &Config{LogStream: "stderr"}, os.Stderr}, + {"valid log file survives SetDefaultOutput", &Config{LogFile: tmpFile, LogStream: "stderr"}, nil}, } - // Verify it's a file we can write to - if output != nil { - defer output.Close() + check := func(t *testing.T, cfg *Config, want io.Writer, output io.Writer) { + t.Helper() - _, err := output.WriteString("test") - if err != nil { - t.Errorf("Failed to write to log file: %v", err) + if want != nil { + if output != want { + t.Errorf("Expected %v, got: %v", want, output) + } + + return } + + file, ok := output.(*os.File) + if !ok || file.Name() != cfg.LogFile { + t.Errorf("Expected file %s, got: %v (%T)", cfg.LogFile, output, output) + + return + } + + file.Close() } + + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + check(t, tt.cfg, tt.want, resolveOutput(tt.cfg)) + + // A binary calling SetDefaultOutput must not redirect a handler already + // bound to an explicit file or stream. + SetDefaultOutput(io.Discard) + + check(t, tt.cfg, tt.want, resolveOutput(tt.cfg)) + }) + } +} + +// TestSetDefaultOutputChangesDefaultWriterTarget verifies the exported +// SetDefaultOutput function redirects the shared defaultWriter used by resolveOutput. +func TestSetDefaultOutputChangesDefaultWriterTarget(t *testing.T) { + t.Cleanup(func() { defaultWriter.Set(os.Stdout) }) + + var dest bytes.Buffer + + SetDefaultOutput(&dest) + + if _, err := defaultWriter.Write([]byte("hello")); err != nil { + t.Fatalf("Write failed: %v", err) + } + + if dest.String() != "hello" { + t.Errorf("Expected SetDefaultOutput to redirect defaultWriter, got: %q", dest.String()) + } +} + +// TestSetDefaultOutputRedirectsAlreadyCachedLogger is the key regression test for the +// cached-logger problem described in #2009: a *slog.Logger created (and derived via +// .With, mirroring `var logger = logging.Logger(component)`) BEFORE the writer target +// changes must still observe the new target afterward, because slog binds a handler to +// a writer once, but the writer itself can be redirected. +func TestSetDefaultOutputRedirectsAlreadyCachedLogger(t *testing.T) { + var oldDest, newDest bytes.Buffer + + sw := newSwitchableWriter(&oldDest) + handler := slog.NewJSONHandler(sw, &slog.HandlerOptions{Level: slog.LevelInfo}) + + // Simulates `var logger = logging.Logger("cached")`, executed at package + // var-init time, i.e. before any binary main() (and any writer redirect) runs. + cachedLogger := slog.New(handler).With("component", "cached") + + cachedLogger.Info("before switch") + + if !strings.Contains(oldDest.String(), "before switch") { + t.Fatalf("Expected message in oldDest before switch, got: %s", oldDest.String()) + } + + // Redirect the writer - analogous to SetDefaultOutput being called from a + // binary's main() after cached loggers already exist. + sw.Set(&newDest) + + cachedLogger.Info("after switch", "extra", "data") + + if strings.Contains(newDest.String(), "before switch") { + t.Error("Old message leaked into newDest") + } + + if !strings.Contains(newDest.String(), "after switch") { + t.Fatalf("Expected new message in newDest, got: %s", newDest.String()) + } + + if strings.Contains(oldDest.String(), "after switch") { + t.Error("New message incorrectly went to oldDest") + } + + // Verify format, level, and With-attributes all still work post-switch. + var parsed map[string]any + if err := json.Unmarshal([]byte(strings.TrimSpace(newDest.String())), &parsed); err != nil { + t.Fatalf("Post-switch output is not valid JSON: %v\nOutput: %s", err, newDest.String()) + } + + if parsed["component"] != "cached" { + t.Errorf("Expected component='cached' to survive the switch, got: %v", parsed["component"]) + } + + if parsed["extra"] != "data" { + t.Errorf("Expected extra='data', got: %v", parsed["extra"]) + } + + if parsed["msg"] != "after switch" { + t.Errorf("Expected msg='after switch', got: %v", parsed["msg"]) + } +} + +// TestSwitchableWriterPreservesLevelFiltering verifies that redirecting the writer +// doesn't disturb the handler's level filtering (Debug still suppressed below Info). +func TestSwitchableWriterPreservesLevelFiltering(t *testing.T) { + var dest bytes.Buffer + + sw := newSwitchableWriter(io.Discard) + handler := slog.NewTextHandler(sw, &slog.HandlerOptions{Level: slog.LevelInfo}) + logger := slog.New(handler) + + sw.Set(&dest) + + logger.Debug("should be filtered") + logger.Info("should appear") + + if strings.Contains(dest.String(), "should be filtered") { + t.Error("Debug message should have been filtered by level") + } + + if !strings.Contains(dest.String(), "should appear") { + t.Errorf("Expected Info message to appear, got: %s", dest.String()) + } +} + +// TestSetDefaultOutputIsConcurrencySafe exercises concurrent writes and target swaps to +// catch data races (run with -race). +func TestSetDefaultOutputIsConcurrencySafe(t *testing.T) { + sw := newSwitchableWriter(io.Discard) + + var wg sync.WaitGroup + + for range 20 { + wg.Add(2) + + go func() { + defer wg.Done() + + _, _ = sw.Write([]byte("x")) + }() + + go func() { + defer wg.Done() + + sw.Set(io.Discard) + }() + } + + wg.Wait() } // TestLoggerFunction verifies Logger() creates component-specific loggers.