charmbracelet / charmbracelet/log
bug: spurious panic when logging concurrently
- Dominant language
- Go
- Stars
- 3.4k
- Forks
- 103
- PR merge metrics
- No merged PRs in 30d
Description
### Describe the bug
Thanks for charmlog, it made my day converting [`quitsh`](https://github.com/sdsc-ordes/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: ...`). *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 `` 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`](https://github.com/sdsc-ordes/quitsh/blob/96efd8fd486cb9e0af85ef70b7f6c98aa07b3467/pkg/log/log.go) as following **once** per process where I afterwards run some goroutines:
```go
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.
Contributor guide
Research direction
Start with the supplied stack trace, especially logger.go's SetOutput path and termenv's output.go/color.go calls, then compare concurrent logger creation and WithPrefix use with the setup in pkg/log/log.go. A useful result would reproduce the panic or terminal escape-code output and provide a regression test showing concurrent logging completes without either symptom.
Written by the indexing model from the issue text.
Assessment
- Tech stack
- go
- Domain
- observability-sre
- Issue type
- Bug
- Difficulty
- 4/5
- Estimated time
- 3-5 days
- Activity status
- Stale
- Clarity
- Needs clarification
- Newbie friendliness
- 25/100