charmbracelet / charmbracelet/log

bug: spurious panic when logging concurrently

Open
#176 3 comments 0 reactions 0 assignees View on GitHub
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

Open the contributing 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

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.