bug: spurious panic when logging concurrently

[gabyx]

Describe the bug

Thanks for charmlog, it made my day converting quitsh to some concurrent execution while having a nice logger with prefixes, however:

I have weird bug, which is hard to reproduce. The charmlog changes colors and also after executing the program it leaves traces of terminal escape codes on my prompt (excute: <garbage>...). At rare times it also panics under concurrent load (really rare).

╭─   /persist/repos/custodian   feat/deps *30 !9 ?1 ····························  20s ▼  impure  09:03:17
╰─❯ g
execute: ffff/ffff/ffff\[62;1R]11;rgb:1212/2626/3737\[62;1R

I setup the charmlog once and then do some goroutines which all have a different logger with logger.WithPrefix(...).

• The crash appears sometimes, and the panic only occured once so far, so I guess it seems its a racecondition internally.
• Also setting logger.SetColorProfile(termenv.Ascii) does not help, the <garbage> still appears.

Maybe I can help finding the root cause of this, as its quite annoying =).

08:21:01  INFO  Executing runner ... args="&{ComponentDir:/persist/repos/custodian/tools/quitsh TargetID:quitsh::lint StepIndex:0 RunnerIndex:0 RunnerID:custodian::lint-go Toolchain:lint-go}"
08:21:01  INFO  Find components by patterns. patterns=[*] root=/persist/repos/custodian
08:21:01  INFO  Executing runner ... args="&{ComponentDir:/persist/repos/custodian/components/contract-manager TargetID:contract-manager::lint StepIndex:0 RunnerIndex:0 RunnerID:custodian::lint-go Toolchain:lint-go}"
08:21:01  INFO  Find components by patterns. patterns=[*] root=/persist/repos/custodian
panic: runtime error: index out of range [2] with length 2

goroutine 1 [running]:
github.com/muesli/termenv.xTermColor({0xc000163520, 0x19})
        /persist/repos/custodian/.devenv/state/go/pkg/mod/github.com/muesli/termenv@v0.16.0/color.go:139 +0x39f
github.com/muesli/termenv.Output.foregroundColor({0xffffffffffffffff, {0xd48980, 0xc00011e040}, {0xd4b8d0, 0x12c9f80}, 0x0, 0x0, 0x1, 0xc00029a4d0, {0xd48fa0, ...}, ...})
        /persist/repos/custodian/.devenv/state/go/pkg/mod/github.com/muesli/termenv@v0.16.0/termenv_unix.go:82 +0x4a
github.com/muesli/termenv.(*Output).ForegroundColor.func1()
        /persist/repos/custodian/.devenv/state/go/pkg/mod/github.com/muesli/termenv@v0.16.0/output.go:143 +0x78
sync.(*Once).doSlow(0x12aa1a0?, 0xc00028c8c0?)
        /nix/store/5xvi25nqmbrg58aixp4zgczilfnp7pwg-go-1.24.3/share/go/src/sync/once.go:78 +0xab
sync.(*Once).Do(...)
        /nix/store/5xvi25nqmbrg58aixp4zgczilfnp7pwg-go-1.24.3/share/go/src/sync/once.go:69
github.com/muesli/termenv.(*Output).ForegroundColor(0xc0001dc900)
        /persist/repos/custodian/.devenv/state/go/pkg/mod/github.com/muesli/termenv@v0.16.0/output.go:147 +0x5d
github.com/charmbracelet/log.(*Logger).SetOutput.WithColorCache.func1(0xc0001dc900)
        /persist/repos/custodian/.devenv/state/go/pkg/mod/github.com/muesli/termenv@v0.16.0/output.go:110 +0x1f
github.com/muesli/termenv.NewOutput({0xd48980, 0xc00011e040}, {0xc000261d40, 0x1, 0xc000218c30?})
        /persist/repos/custodian/.devenv/state/go/pkg/mod/github.com/muesli/termenv@v0.16.0/output.go:80 +0x174
github.com/charmbracelet/lipgloss.NewRenderer(...)
        /persist/repos/custodian/.devenv/state/go/pkg/mod/github.com/charmbracelet/lipgloss@v1.1.0/renderer.go:46
github.com/charmbracelet/log.(*Logger).SetOutput(0xc00015e540, {0xd48980, 0xc00011e040})
        /persist/repos/custodian/.devenv/state/go/pkg/mod/github.com/charmbracelet/log@v0.4.2/logger.go:287 +0x1bc
github.com/charmbracelet/log.NewWithOptions({0xd48980, 0xc00011e040}, {0x0, {0x0, 0x0}, 0x0, {0x0, 0x0}, 0x0, 0x0, ...})
        /persist/repos/custodian/.devenv/state/go/pkg/mod/github.com/charmbracelet/log@v0.4.2/pkg.go:67 +0x1e6
github.com/charmbracelet/log.New(...)
        /persist/repos/custodian/.devenv/state/go/pkg/mod/github.com/charmbracelet/log@v0.4.2/pkg.go:46
github.com/sdsc-ordes/quitsh/pkg/log.init()
        /persist/repos/custodian/.devenv/state/go/pkg/mod/github.com/sdsc-ordes/quitsh@v0.27.1-0.20250630055803-96efd8fd486c/pkg/log/log.go:20 +0x45

In the package of interest I setup the logger with Setup as following once per process where I afterwards run some goroutines:

var ForceColorInCI = true //nolint:gochecknoglobals // Intended, to be disabled if really needed.
const TraceLevel = chlog.DebugLevel - 10

// Our global default logger. Yes singletons are code-smell,
// but we allow it for the logging functionality.
var globalLogger = logger{ //nolint:gochecknoglobals // Accepted as only for logging.
	l: chlog.New(os.Stderr),
}

// Setup sets up the default loggers .
func Setup(level string) (err error) {
	l, err := initLog(level)
	if err != nil {
		return
	}

	globalLogger = l

	return
}

func ciRunning() bool {
	return os.Getenv("CI") == "true"
}

func initLog(level string) (logger, error) {
	l := chlog.NewWithOptions(
		os.Stderr, chlog.Options{
			ReportCaller:    false,
			ReportTimestamp: true,
			TimeFormat:      time.TimeOnly,
		})

	err := setLevel(l, level)
	if err != nil {
		return logger{}, err
	}

	styles := getStyles()
	l.SetStyles(styles)

	if ciRunning() && ForceColorInCI {
		// We force here the color profile for CI.
		l.SetColorProfile(termenv.TrueColor)
	}

	return logger{l: l}, nil
}

func getStyles() *chlog.Styles {
	styles := chlog.DefaultStyles()

	styles.Message = lipgloss.NewStyle().
		Foreground(lipgloss.AdaptiveColor{Light: "#1b4796", Dark: "#58A6FF"})

	styles.Levels[TraceLevel] = lipgloss.NewStyle().
		SetString("TRACE").
		Padding(0, 1, 0, 1).
		Background(lipgloss.Color("#a4a4a4")).
		Foreground(lipgloss.Color("0")).Bold(true)

	styles.Levels[chlog.DebugLevel] = lipgloss.NewStyle().
		SetString("DEBUG").
		Padding(0, 1, 0, 1).
		Background(lipgloss.Color("#00e6ff")).
		Foreground(lipgloss.Color("0")).Bold(true)

	styles.Levels[chlog.InfoLevel] = lipgloss.NewStyle().
		SetString("INFO").
		Padding(0, 1, 0, 1).
		Background(lipgloss.Color("#00c41a")).
		Foreground(lipgloss.Color("0")).Bold(true)

	styles.Levels[chlog.WarnLevel] = lipgloss.NewStyle().
		SetString("WARN").
		Padding(0, 1, 0, 1).
		Background(lipgloss.Color("#ff7400")).
		Foreground(lipgloss.Color("0")).Bold(true)

	styles.Levels[chlog.ErrorLevel] = lipgloss.NewStyle().
		SetString("ERROR").
		Padding(0, 1, 0, 1).
		Background(lipgloss.Color("#ff0000")).
		Foreground(lipgloss.Color("0")).Bold(true)

	styles.Prefix = lipgloss.NewStyle().
		Foreground(lipgloss.AdaptiveColor{Light: "#007399", Dark: "#44b5c3"}).
		Italic(true)

	styles.Caller = lipgloss.NewStyle().Italic(true)

	styles.Key = lipgloss.NewStyle().
		Foreground(lipgloss.AdaptiveColor{Light: "#007399", Dark: "#44b5c3"}).
		Bold(true)

	styles.Keys["err"] = lipgloss.NewStyle().Foreground(lipgloss.Color("#ff0000"))
	styles.Keys["error"] = lipgloss.NewStyle().Foreground(lipgloss.Color("#ff0000"))
	styles.Values["err"] = lipgloss.NewStyle().Bold(true)
	styles.Values["error"] = lipgloss.NewStyle().Bold(true)

	return styles
}

Setup

Please complete the following information along with version numbers, if applicable.

• OS [e.g. Ubuntu, macOS]: NixOS
• Shell [e.g. zsh, fish]: zsh
• Terminal Emulator [e.g. kitty, iterm]: wezterm
• Terminal Multiplexer [e.g. tmux]: none

Note: you might encounter rendering issues if your locale does not use
UTF-8 encoding. Please check your locale (locale on POSIX systems) to
see what encoding is being used by your system.

To Reproduce

Still figuring out...

Source Code

Cannot, since the bug is quite subtle. Let me help find the root cause of this. Maybe the issue also lies withing my setup.

Expected behavior

No panic when using in concurrent logging.

[gabyx]

Also I thought it might be due to initializing the globalLogger variable not thread-safe, since charmlog under the hood sends escape code to the terminal (for the color profile), but also the below does not help:
How can I ensure charmlog only queries the terminal once and for sure not concurrently?

// Our global default logger. Yes singletons are code-smell,
// but we allow it for the logging functionality.
//
//nolint:gochecknoglobals // intended
var (
	globalLogger logger
	initOnce     sync.Once
)

//nolint:gochecknoinits // intended
func init() {
	initOnce.Do(func() {
		// This block of code is guaranteed to run exactly once.
		// We perform a basic, default initialization here.
		globalLogger = logger{
			l: chlog.New(os.Stderr),
		}
	})
}

[gabyx]

I think I found the root cause of this problem:
E.g. I start multiple processes (each coroutine starts one), and each process will again do initialize a logger which will send query color properties from the terminal which is race condition.

Do you know how I can avoid that termenv underneath queries again the properties?

[aymanbagabas]

Hi @gabyx,

Do you know how I can avoid that termenv underneath queries again the properties?

One way is to use the v2-exp branch which has depends on the Lip Gloss v2 and doesn't have that problem.