Skip to content

fix(io): make logger mode concurrency-safe and fix writer mode restore #112

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.

Sign up for GitHub

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

Merged
jahvon merged 1 commit into from
Jul 26, 2026
Merged

fix(io): make logger mode concurrency-safe and fix writer mode restore #112

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
58 changes: 42 additions & 16 deletions io/logger.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -3,6 +3,7 @@ package io
import (
"fmt"
"os"
"sync"
"time"

"charm.land/lipgloss/v2"
Expand All @@ -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)
Expand Down Expand Up @@ -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 {
Expand Down Expand Up @@ -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
Expand All @@ -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
Expand All @@ -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
Expand All @@ -243,15 +269,15 @@ 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)
}

func (l *StandardLogger) Errorf(msg string, args ...any) {
l.syncLoggerFormat()
switch l.mode {
switch l.currentMode() {
case Text:
l.PlainTextError(safeSprintf(msg, args...))
return
Expand All @@ -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
Expand All @@ -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)
Expand All @@ -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...)
Expand All @@ -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()
Expand All @@ -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()
Expand All @@ -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()
Expand All @@ -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()
Expand Down Expand Up @@ -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, "":
Expand All @@ -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())
Expand All @@ -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())
Expand All @@ -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
}

Expand Down
32 changes: 27 additions & 5 deletions io/output.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand All @@ -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)
}
}()
Expand Down Expand Up @@ -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)
}
}()
Expand Down
54 changes: 54 additions & 0 deletions io/output_race_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -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)
}
}
Loading