The log output is incorrect.

[Charliego3]

OS: macOS Venture 13.2.1 Terminal: kitty go version: go1.20.2 darwin/amd64

There are many characters related to colors appearing in the log.

ctx, cancel := context.WithCancel(context.Background())
for _, c := range config.Websockets {
    opts := log.Options{
        ReportTimestamp: true,
        ReportCaller:    true,
        TimeFormat:      time.DateTime,
        Level:           log.DebugLevel,
    }
    go (&Orderer{ctx: ctx, opts: opts}).Start(c)
}

Create an instance using o.logger = log.NewWithOptions(os.Stdout, o.opts) in the Start function.

This issue is random and not every log will have it. When restarting the program, it may not occur for a long time, but sometimes it can happen quickly. Why does this situation happen? Or, how can I solve it?

[aymanbagabas]

Hi @Charliego93, can you reproduce this with a different terminal emulator? Could you come up with a minimal reproducible code?

[Charliego3]

Hi @Charliego93, what terminal are you using?

The same issue occurs in both the Terminal application that comes with macOS and in VSCode.

macOS terminal

vscode

[Charliego3]

@aymanbagabas Here is a reproducible example, you can take a look.

package main

import (
    "context"
    "fmt"
    "os"
    "os/signal"
    "syscall"
    "testing"
    "time"

    "github.com/charmbracelet/log"
)

type Runner struct{}

type Client struct {
    logger *log.Logger
    ch     chan string
    ctx    context.Context
}

func NewClient(ctx context.Context, opts *log.Options, ch chan string) *Client {
    return &Client{
        logger: log.NewWithOptions(os.Stdout, *opts),
        ch:     ch,
        ctx:    ctx,
    }
}

func (c *Client) output() {
    ticker := time.NewTicker(time.Millisecond * 300)
    var count = 1
    for {
        select {
        case t := <-ticker.C:
            c.logger.Info("Client output")
            c.ch <- fmt.Sprintf("Client output: %v", t)
            count++
        case <-c.ctx.Done():
            c.logger.Info("Client exit")
            return
        }
    }
}

func (r *Runner) Run(ctx context.Context, opts log.Options, idx int) {
    logger := log.NewWithOptions(os.Stdout, opts)

    ch := make(chan string)
    for i := 0; i < 2; i++ {
        go (NewClient(ctx, &opts, ch)).output()
    }

    for {
        select {
        case t := <-ch:
            logger.Debug("Receive", "idx", idx, "msg", t)
        case <-ctx.Done():
            logger.Info("Done")
            return
        }
    }
}

func TestOutput(t *testing.T) {
    opts := log.Options{
        ReportTimestamp: true,
        ReportCaller:    true,
        TimeFormat:      time.DateTime,
        Level:           log.DebugLevel,
    }

    ctx, cancel := context.WithCancel(context.Background())
    go (&Runner{}).Run(ctx, opts, 1)

    stoper := make(chan os.Signal, 3)
    signal.Notify(stoper, syscall.SIGTERM, syscall.SIGINT, syscall.SIGQUIT)
    <-stoper
    cancel()
    time.Sleep(time.Second)
    log.Info(“Program exit")
}

[muesli]

There are many characters related to colors appearing in the log.

What you're seeing is a logger instance querying the terminal for its color support & settings.

Create an instance using o.logger = log.NewWithOptions(os.Stdout, o.opts) in the Start function.

This will create multiple logger instances, all operating on the same output os.Stdout. One instance of o.logger will interfere with another querying the same terminal/output.

We can fix/prevent concurrently querying the terminal, but mind you that this kind of usage will still lead to unexpected problems. Multiple logger instances might try to write to the same output at the same time, creating interleaved output.

You will have to share one logger instance among all clients or create a locking mechanism that synchronizes logger initialization and printing.

[Charliego3]

Hi @muesli, Indeed, as you said, it seems that the issue only occurs when there are multiple instances, and it will also occur with the log.With() or log.WithPrefix() which returns a subLog. However, it’s not very reasonable to have only one instance in a project, and in libraries, a logger instance must be passed in.

[aymanbagabas]

@Charliego93 could you try if https://github.com/charmbracelet/log/pull/52 solves the issue?

[Charliego3]

@aymanbagabas After multiple tests, the previous issue did not occur again, which is quite perfect.

[aymanbagabas]

Fixed in v0.2.1