From 9093cc8859d33a625c3287c61cc4c3921f2c737a Mon Sep 17 00:00:00 2001 From: Jahvon Dockery Date: Sun, 26 Jul 2026 10:57:59 -0400 Subject: [PATCH] fix(io): make logger mode concurrency-safe and fix writer restore MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Std{Out,Err}Writer temporarily flip the shared logger's mode on every write. When a command's stdout and stderr are copied concurrently (os/exec uses one goroutine per stream), those writers read (LogMode) and write (SetMode) the StandardLogger.mode field with no synchronization — a data race under -race. - Guard StandardLogger.mode with a RWMutex (modeMu). The underlying charm log handlers are already internally synchronized, so only this field needed it. - Serialize the writers' flip/render/restore sequence with a second mutex (writeMu), exposed to the writers in-package, so concurrent writers cannot interleave and render each other's output in the wrong mode. - Fix StdOutWriter, which reassigned its saved mode after flipping and so never restored the logger's original mode (StdErrWriter was already correct). Both writers now share one flip/restore path guarded by a `flipped` flag. Adds a regression test that drives both writers concurrently with a mode different from the logger's; it reports DATA RACE under -race without the fix, and also asserts the logger's mode is restored afterward. Co-Authored-By: Claude Opus 4.8 (1M context) --- io/logger.go | 58 ++++++++++++++++++++++++++++++------------ io/output.go | 32 +++++++++++++++++++---- io/output_race_test.go | 54 +++++++++++++++++++++++++++++++++++++++ 3 files changed, 123 insertions(+), 21 deletions(-) create mode 100644 io/output_race_test.go diff --git a/io/logger.go b/io/logger.go index e9b59b4..d42fb0c 100644 --- a/io/logger.go +++ b/io/logger.go @@ -3,6 +3,7 @@ package io import ( "fmt" "os" + "sync" "time" "charm.land/lipgloss/v2" @@ -29,6 +30,15 @@ type StandardLogger struct { outFile *os.File outWriter *colorprofile.Writer // color-profile-aware writer for styled output exitFunc func(msg string, args ...any) + + // modeMu guards the mode field. Std{Out,Err}Writer temporarily flip the mode on every + // write, so a command's stdout and stderr (copied by os/exec in separate goroutines) can + // read and write it concurrently. The underlying charm log handlers are internally + // synchronized; only this field needs protection. + modeMu sync.RWMutex + // writeMu serializes the Std{Out,Err}Writer flip/render/restore sequence so concurrent + // writers cannot interleave and render each other's output in the wrong mode. + writeMu sync.Mutex } type LoggerOptions func(*StandardLogger) @@ -122,17 +132,33 @@ func (l *StandardLogger) SetMode(mode LogMode) { if mode == "" { return } + l.modeMu.Lock() l.mode = mode + l.modeMu.Unlock() + // applyHumanReadableFormat mutates the charm log handler, which is internally + // synchronized, so it is safe to call outside modeMu. applyHumanReadableFormat(l.outHandler, l.theme, mode, l.outFile) } func (l *StandardLogger) LogMode() LogMode { + return l.currentMode() +} + +// currentMode returns the active mode under a read lock, defaulting to Text when unset. +func (l *StandardLogger) currentMode() LogMode { + l.modeMu.RLock() + defer l.modeMu.RUnlock() if l.mode == "" { return Text } return l.mode } +// acquireWriteLock and releaseWriteLock let the Std{Out,Err}Writers serialize their +// flip/render/restore sequence (see writeMu). +func (l *StandardLogger) acquireWriteLock() { l.writeMu.Lock() } +func (l *StandardLogger) releaseWriteLock() { l.writeMu.Unlock() } + func applyHumanReadableFormat(handler *log.Logger, style themes.Theme, mode LogMode, out *os.File) { handler.SetReportTimestamp(true) if mode == JSON { @@ -193,7 +219,7 @@ func (l *StandardLogger) Println(data string) { func (l *StandardLogger) Infof(msg string, args ...any) { l.syncLoggerFormat() - switch l.mode { + switch l.currentMode() { case Text: l.PlainTextInfo(safeSprintf(msg, args...)) return @@ -209,7 +235,7 @@ func (l *StandardLogger) Infof(msg string, args ...any) { func (l *StandardLogger) Noticef(msg string, args ...any) { l.syncLoggerFormat() - switch l.mode { + switch l.currentMode() { case Text: l.PlainTextNotice(safeSprintf(msg, args...)) return @@ -225,7 +251,7 @@ func (l *StandardLogger) Noticef(msg string, args ...any) { func (l *StandardLogger) Debugf(msg string, args ...any) { l.syncLoggerFormat() - switch l.mode { + switch l.currentMode() { case Text: l.PlainTextDebug(safeSprintf(msg, args...)) return @@ -243,7 +269,7 @@ func (l *StandardLogger) WrapError(err error, msg string) { if msg == "" { l.Error(err.Error()) return - } else if l.mode == Hidden { + } else if l.currentMode() == Hidden { return } l.Error(err.Error(), "err", err) @@ -251,7 +277,7 @@ func (l *StandardLogger) WrapError(err error, msg string) { func (l *StandardLogger) Errorf(msg string, args ...any) { l.syncLoggerFormat() - switch l.mode { + switch l.currentMode() { case Text: l.PlainTextError(safeSprintf(msg, args...)) return @@ -267,7 +293,7 @@ func (l *StandardLogger) Errorf(msg string, args ...any) { func (l *StandardLogger) Warnf(msg string, args ...any) { l.syncLoggerFormat() - switch l.mode { + switch l.currentMode() { case Text: l.PlainTextWarn(safeSprintf(msg, args...)) return @@ -288,7 +314,7 @@ func (l *StandardLogger) FatalErr(err error) { func (l *StandardLogger) Fatalf(msg string, args ...any) { l.syncLoggerFormat() formatted := safeSprintf(msg, args...) - switch l.mode { + switch l.currentMode() { case Text: l.PlainTextError(formatted) l.exitFunc(formatted) @@ -305,7 +331,7 @@ func (l *StandardLogger) Fatalf(msg string, args ...any) { func (l *StandardLogger) Info(msg string, kv ...any) { l.syncLoggerFormat() - if l.mode == Hidden { + if l.currentMode() == Hidden { return } l.outHandler.Info(msg, kv...) @@ -315,7 +341,7 @@ func (l *StandardLogger) Info(msg string, kv ...any) { } func (l *StandardLogger) Notice(msg string, kv ...any) { - if l.mode == Hidden { + if l.currentMode() == Hidden { return } l.syncLoggerFormat() @@ -326,7 +352,7 @@ func (l *StandardLogger) Notice(msg string, kv ...any) { } func (l *StandardLogger) Debug(msg string, kv ...any) { - if l.mode == Hidden { + if l.currentMode() == Hidden { return } l.syncLoggerFormat() @@ -337,7 +363,7 @@ func (l *StandardLogger) Debug(msg string, kv ...any) { } func (l *StandardLogger) Error(msg string, kv ...any) { - if l.mode == Hidden { + if l.currentMode() == Hidden { return } l.syncLoggerFormat() @@ -348,7 +374,7 @@ func (l *StandardLogger) Error(msg string, kv ...any) { } func (l *StandardLogger) Warn(msg string, kv ...any) { - if l.mode == Hidden { + if l.currentMode() == Hidden { return } l.syncLoggerFormat() @@ -443,7 +469,7 @@ func (l *StandardLogger) Flush() error { } func (l *StandardLogger) syncLoggerFormat() { - switch l.mode { + switch l.currentMode() { case JSON: l.outHandler.SetFormatter(log.JSONFormatter) case Logfmt, Text, "": @@ -470,7 +496,7 @@ func defaultExit(_ string, _ ...any) { // --- TaskAwareLogger implementation --- func (l *StandardLogger) PrintWithTask(task *TaskContext, line string) { - if l.mode == Hidden { + if l.currentMode() == Hidden { return } prefix := taskPrefix(task, l.theme.ColorPalette()) @@ -483,7 +509,7 @@ func (l *StandardLogger) PrintWithTask(task *TaskContext, line string) { } func (l *StandardLogger) PrintErrWithTask(task *TaskContext, line string) { - if l.mode == Hidden { + if l.currentMode() == Hidden { return } prefix := taskPrefix(task, l.theme.ColorPalette()) @@ -497,7 +523,7 @@ func (l *StandardLogger) PrintErrWithTask(task *TaskContext, line string) { } func (l *StandardLogger) PrintTaskSummary(tasks []*TaskContext) { - if l.mode == Hidden || len(tasks) == 0 { + if l.currentMode() == Hidden || len(tasks) == 0 { return } diff --git a/io/output.go b/io/output.go index 256a681..f3c355f 100644 --- a/io/output.go +++ b/io/output.go @@ -5,6 +5,23 @@ import ( "strings" ) +// serializedLogger is implemented by loggers (e.g. StandardLogger) that can serialize the +// writers' mode flip/render/restore sequence. When available, Std{Out,Err}Writer hold the +// lock for the whole Write so a command's concurrently-copied stdout and stderr streams +// cannot interleave and render each other's output in the wrong mode. +type serializedLogger interface { + acquireWriteLock() + releaseWriteLock() +} + +func serializeWrite(logger Logger) func() { + if sl, ok := logger.(serializedLogger); ok { + sl.acquireWriteLock() + return sl.releaseWriteLock + } + return func() {} +} + type StdOutWriter struct { LogFields []any Logger Logger @@ -13,13 +30,15 @@ type StdOutWriter struct { } func (w StdOutWriter) Write(p []byte) (n int, err error) { + defer serializeWrite(w.Logger)() + curMode := w.Logger.LogMode() - if w.LogMode != nil && (*w.LogMode != "" && *w.LogMode != curMode) { + flipped := w.LogMode != nil && *w.LogMode != "" && *w.LogMode != curMode + if flipped { w.Logger.SetMode(*w.LogMode) - curMode = w.Logger.LogMode() } defer func() { - if w.LogMode != nil && *w.LogMode != curMode { + if flipped { w.Logger.SetMode(curMode) } }() @@ -55,12 +74,15 @@ type StdErrWriter struct { } func (w StdErrWriter) Write(p []byte) (n int, err error) { + defer serializeWrite(w.Logger)() + curMode := w.Logger.LogMode() - if w.LogMode != nil && (*w.LogMode != "" && *w.LogMode != curMode) { + flipped := w.LogMode != nil && *w.LogMode != "" && *w.LogMode != curMode + if flipped { w.Logger.SetMode(*w.LogMode) } defer func() { - if w.LogMode != nil && *w.LogMode != curMode { + if flipped { w.Logger.SetMode(curMode) } }() diff --git a/io/output_race_test.go b/io/output_race_test.go new file mode 100644 index 0000000..a2b7887 --- /dev/null +++ b/io/output_race_test.go @@ -0,0 +1,54 @@ +package io_test + +import ( + "os" + "sync" + "testing" + + "github.com/flowexec/tuikit/io" +) + +// TestStdWriters_ConcurrentDoesNotRace drives a StdOutWriter and StdErrWriter concurrently, +// the way os/exec copies a command's two output streams. Both writers temporarily flip the +// shared logger's mode; before serialization this raced on the mode field. The writers request +// a mode different from the logger's so the flip/restore path is exercised. Run with -race. +func TestStdWriters_ConcurrentDoesNotRace(t *testing.T) { + f, err := os.CreateTemp(t.TempDir(), "tuikit-log") + if err != nil { + t.Fatalf("create temp file: %v", err) + } + t.Cleanup(func() { _ = f.Close() }) + + logger := io.NewLogger(io.WithOutput(f), io.WithMode(io.Text)) + desired := io.Logfmt + out := io.StdOutWriter{Logger: logger, LogMode: &desired} + errW := io.StdErrWriter{Logger: logger, LogMode: &desired} + + const writesPerStream = 100 + var wg sync.WaitGroup + wg.Add(2) + go func() { + defer wg.Done() + for i := 0; i < writesPerStream; i++ { + if _, wErr := out.Write([]byte("stdout line\n")); wErr != nil { + t.Errorf("stdout write: %v", wErr) + return + } + } + }() + go func() { + defer wg.Done() + for i := 0; i < writesPerStream; i++ { + if _, wErr := errW.Write([]byte("stderr line\n")); wErr != nil { + t.Errorf("stderr write: %v", wErr) + return + } + } + }() + wg.Wait() + + // The logger's mode must be restored to its original value after the writers finish. + if logger.LogMode() != io.Text { + t.Errorf("logger mode = %q after writes, want %q", logger.LogMode(), io.Text) + } +}