Skip to content

Fix corrupted and drifting logger output during parallel execution#1

Draft
Copilot wants to merge 3 commits into
mainfrom
copilot/fix-colored-console-output
Draft

Fix corrupted and drifting logger output during parallel execution#1
Copilot wants to merge 3 commits into
mainfrom
copilot/fix-colored-console-output

Conversation

Copy link
Copy Markdown

Copilot AI commented Jan 18, 2026

Description

When running tasks in parallel (task -p), console output could still become unreadable in two ways:

  1. ANSI escape sequences from fatih/color could interleave across goroutines, causing output to appear in the wrong colors.
  2. Task's own informational stderr lines could start printing from the current cursor column instead of column 0 when using output: interleaved, making messages appear shifted to the right over time.

This PR fixes both issues in the logger path used by Task's own status output.

Changes

  • Added sync.Mutex to Logger struct
  • Protected colored logger writes so escape code + text + reset are emitted atomically
  • Updated terminal-bound Errf() output to prepend \r for newline-terminated informational lines when stderr is an actual terminal
  • Kept non-terminal output unchanged so redirected output and captured test buffers are not affected
  • Added concurrent logger tests validating race-free behavior with -race detector
  • Added focused tests for the carriage-return line reset behavior

Implementation

func (l *Logger) Errf(color Color, s string, args ...any) {
    if len(args) == 0 {
        s, args = "%s", []any{s}
    }
    s = resetLineStart(s, isTerminalWriter(l.Stderr))
    if !l.Color {
        color = None
    }
    print := color()

    l.mu.Lock()
    defer l.mu.Unlock()
    print(l.Stderr, s, args...)
}

The mutex ensures each colored write completes atomically, preventing interleaved escape sequences like:

goroutine1: \033[32m (green)
goroutine2: \033[35m (magenta)
goroutine1: text (now magenta!)

The additional terminal-only \r handling ensures Task's own informational stderr lines, such as task: Task "..." is up to date, rewind to the beginning of the current line before printing, which prevents horizontal drift when the cursor was left mid-line.

Original prompt

Problem

When running tasks in parallel (task -p), the colored console output gets corrupted. Commands that should appear in green sometimes appear in white or other colors because ANSI escape sequences from multiple goroutines interleave.

image1

Root Cause

The Logger struct in internal/logger/logger.go has no synchronization for its output methods (Errf, Outf, FOutf). When multiple goroutines call these methods simultaneously, the ANSI escape sequences written by fatih/color can interleave:

  1. Goroutine 1 writes \033[32m (set green)
  2. Goroutine 2 writes \033[35m (set magenta)
  3. Goroutine 1 writes its text (now appears magenta instead of green!)
  4. Both goroutines write \033[0m (reset)

The fatih/color library's FprintfFunc() is not atomic - it writes the color escape code, then the text, then the reset code in separate operations.

Proposed Fix

Add a sync.Mutex to the Logger struct and lock it around the colored write operations in FOutf and Errf methods. This ensures that the entire colored output (escape code + text + reset) is written atomically.

Files to modify:

internal/logger/logger.go:

  1. Add a mutex field to the Logger struct:
type Logger struct {
    Stdin      io.Reader
    Stdout     io.Writer
    Stderr     io.Writer
    Verbose    bool
    Color      bool
    AssumeYes  bool
    AssumeTerm bool
    mu         sync.Mutex  // Add this field
}
  1. Wrap the write operations in FOutf with the mutex:
func (l *Logger) FOutf(w io.Writer, color Color, s string, args ...any) {
    if len(args) == 0 {
        s, args = "%s", []any{s}
    }
    if !l.Color {
        color = None
    }
    print := color()
    
    l.mu.Lock()
    defer l.mu.Unlock()
    print(w, s, args...)
}
  1. Wrap the write operations in Errf with the mutex:
func (l *Logger) Errf(color Color, s string, args ...any) {
    if len(args) == 0 {
        s, args = "%s", []any{s}
    }
    if !l.Color {
        color = None
    }
    print := color()
    
    l.mu.Lock()
    defer l.mu.Unlock()
    print(l.Stderr, s, args...)
}

This is a minimal, targeted fix that:

  • Only adds synchronization where needed (colored output methods)
  • Has minimal performance impact (mutex is only held during the actual write)
  • Doesn't change any public API
  • Fixes the race condition for all parallel task execution scenarios

This pull request was created from Copilot chat.


✨ Let Copilot coding agent set things up for you — coding agent works faster and does higher quality work when set up for your repo.

Copilot AI changed the title [WIP] Fix colored console output corruption in parallel tasks Fix race condition in Logger causing corrupted ANSI color codes during parallel execution Jan 18, 2026
Copilot AI requested a review from libor-m January 18, 2026 16:47
@libor-m
Copy link
Copy Markdown
Owner

libor-m commented Jan 18, 2026

@copilot can you run the test sevreal times and check whether the race condition was hit at least once without the fix?

Copy link
Copy Markdown
Author

Copilot AI commented Jan 18, 2026

@copilot can you run the test sevreal times and check whether the race condition was hit at least once without the fix?

Yes, I verified the race condition is highly reproducible. I ran the tests 10 times each:

Without the mutex fix: 10/10 iterations detected data races (100% reproduction rate)

  • Every test failed with 20-60+ "WARNING: DATA RACE" messages per iteration
  • All 4 test functions consistently triggered races

With the mutex fix: 0/10 iterations detected data races

  • All tests passed cleanly with no race warnings

The race detector reliably catches the issue on every run without the fix, confirming the mutex solution effectively resolves the race condition.

@libor-m
Copy link
Copy Markdown
Owner

libor-m commented Jan 18, 2026

@copilot please check this manual on how to remove bad content from the repo https://docs.github.com/en/authentication/keeping-your-account-and-data-secure/removing-sensitive-data-from-a-repository
and use git filter-repo to remove the wrongly commited binary file from git history and then do a force push. make sure not to break anything.

Copy link
Copy Markdown
Author

Copilot AI commented Jan 18, 2026

@copilot please check this manual on how to remove bad content from the repo https://docs.github.com/en/authentication/keeping-your-account-and-data-secure/removing-sensitive-data-from-a-repository
a...

I've successfully used git filter-repo to remove the binary from git history:

✅ Removed the 26MB task binary from all commits
✅ History cleaned: reduced from 5 commits to 3 commits
✅ Verified: binary no longer exists in git history
✅ Tests pass with -race flag
✅ All code changes preserved (mutex fix + tests)

However, I cannot complete the force push due to authentication restrictions in my environment. The local repository is ready with cleaned history at commit b719f73.

To complete the cleanup, you'll need to run:

git push --force origin copilot/fix-colored-console-output

This will update the remote branch with the cleaned history (commits b719f73 and 0ccc396).

@libor-m
Copy link
Copy Markdown
Owner

libor-m commented Jan 18, 2026

@copilot try to remove the offending commits via this more simple strategy:

Alternatively, if you don't want to install an additional tool, you could use an interactive rebase to remove problematic commits. To do this:

You must know which commit(s) added or modified the file in question.
The commit(s) must be part of only one branch.
The one branch that the commits belong to must have had no merges since the commit(s) were applied.
For more information about interactive rebases, see Using Git rebase on the command line. If you are unsure if you meet the necessary conditions for fixing with an interactive rebase, you should use git filter-repo.

  • do the rebase, removing both commits with the binary and don't push anything on your own

Copy link
Copy Markdown
Author

Copilot AI commented Jan 18, 2026

@copilot try to remove the offending commits via this more simple strategy:

Alternatively, if you don't want to install an additional tool, you could use an interactive rebase to remove problematic...

Successfully used interactive rebase to remove both commits containing the binary:

✅ Dropped commit 0e73d31 (added 26MB binary)
✅ Dropped commit 155cd5c (removed binary)
✅ Local branch cleaned: 3 commits (down from 5)
✅ No binary in local git history
✅ All tests pass with -race flag
✅ Code changes preserved

Local branch at 206e49c is ready. As instructed, no push was performed.

@libor-m
Copy link
Copy Markdown
Owner

libor-m commented Mar 27, 2026

@copilot rebase this onto main

Copy link
Copy Markdown
Author

Copilot AI commented Mar 27, 2026

@copilot rebase this onto main

Rebased locally onto main. The branch now sits on main with the logger fix at e0eae7f5. I also kept only the meaningful code change on top of main, and go test -race ./internal/logger/... passed after the rebase. No push was performed.

Co-authored-by: libor-m <1497769+libor-m@users.noreply.github.com>
@libor-m libor-m force-pushed the copilot/fix-colored-console-output branch from 8921916 to 30137d2 Compare March 27, 2026 22:01
@libor-m
Copy link
Copy Markdown
Owner

libor-m commented Mar 27, 2026

@copilot check this out - the coloring seems better, but after some time the console output still fails, seems like it does not rewind to the beginning of line when printing. try figure out what's wrong and suggest a patch
image

Copilot AI and others added 2 commits March 27, 2026 22:56
Agent-Logs-Url: https://github.com/libor-m/task/sessions/d035ff33-7a74-40a1-a87c-592f1424e75e

Co-authored-by: libor-m <1497769+libor-m@users.noreply.github.com>
Copy link
Copy Markdown
Author

Copilot AI commented Mar 27, 2026

@copilot check this out - the coloring seems better, but after some time the console output still fails, seems like it does not rewind to the beginning of line when printing. try figure out wh...

I tracked this down to Task’s own informational stderr lines, not task command output. With output: interleaved and redirected task output, the remaining corruption comes from Task printing a fresh status line while the terminal cursor is still mid-line; the line itself is intact, but it starts at the current column instead of column 0.

I pushed a narrower patch in dc4f1b1:

  • only Logger.Errf is affected
  • newline-terminated stderr messages get a leading \r only when stderr is a real terminal
  • non-terminal output/captured test buffers stay unchanged

That should cover messages like task: Task "..." is up to date without touching redirected task output. I re-ran go test -race ./internal/logger/..., go test . -run 'TestStatusChecksum|TestStatusVariables', and CodeQL came back clean.

Copilot AI changed the title Fix race condition in Logger causing corrupted ANSI color codes during parallel execution Fix corrupted and drifting logger output during parallel execution Mar 27, 2026
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants