search

charmbracelet / log

A minimal, colorful Go logging library 🪵
MIT License
2.4k stars 67 forks source link

fix: deep copy the fields to avoid data race #128

Closed yuguorui closed 6 months ago

yuguorui commented 6 months ago

sl.fields and l.fields reference the the same object, when we create multiple goroutines and bump loggers with the With() method, the golang race detector will complain about this.

codecov[bot] commented 6 months ago

Codecov Report

All modified and coverable lines are covered by tests :white_check_mark:

Project coverage is 82.05%. Comparing base (2338a13) to head (9c66636). Report is 20 commits behind head on main.

Additional details and impacted files ```diff @@ Coverage Diff @@ ## main #128 +/- ## ========================================== + Coverage 80.92% 82.05% +1.13% ========================================== Files 11 11 Lines 739 691 -48 ========================================== - Hits 598 567 -31 + Misses 126 108 -18 - Partials 15 16 +1 ```

:umbrella: View full report in Codecov by Sentry.
:loudspeaker: Have feedback on the report? Share it here.

aymanbagabas commented 6 months ago

LGTM, could you please add a test case for this issue?

yuguorui commented 6 months ago

LGTM, could you please add a test case for this issue?

Sure, this issue is actually discovered by our inner unittests, I have enhanced the existing testing case to detect the issue.

yuguorui commented 6 months ago

Kindly ping again~ @aymanbagabas Could you re-review the new test patch to see if the PR can be merged?

aymanbagabas commented 6 months ago

@yuguorui I can't trigger the test case using master and running go test -race ./..., am I doing something wrong?

yuguorui commented 6 months ago

Sorry, seems I miss one line when I try to construct the minimal producible test, now it should work.

--- a/logger_test.go
+++ b/logger_test.go
@@ -228,6 +228,7 @@ func TestLogWithRaceCondition(t *testing.T) {

                                done.Add(1)
                                go func() {
+                                       l = l.With("arg1", "val1", "arg2", "val2")
                                        l.Info("kinda long log message")
                                        done.Done()
                                }()

And here is the backtrace.

$ go test -race ./... -run TestLogWithRaceCondition -v
=== RUN   TestLogWithRaceCondition
=== RUN   TestLogWithRaceCondition/must_be_run_with_-race
==================
WARNING: DATA RACE
Read at 0x00c0001120c8 by goroutine 10:
  github.com/charmbracelet/log.TestLogWithRaceCondition.func1.2()
      /home/yuguorui/Code/log/logger_test.go:231 +0xef

Previous write at 0x00c0001120c8 by goroutine 12:
  github.com/charmbracelet/log.TestLogWithRaceCondition.func1.2()
      /home/yuguorui/Code/log/logger_test.go:231 +0x11e

Goroutine 10 (running) created at:
  github.com/charmbracelet/log.TestLogWithRaceCondition.func1()
      /home/yuguorui/Code/log/logger_test.go:230 +0x119
  testing.tRunner()
      /snap/go/10585/src/testing/testing.go:1689 +0x21e
  testing.(*T).Run.gowrap1()
      /snap/go/10585/src/testing/testing.go:1742 +0x44

Goroutine 12 (finished) created at:
  github.com/charmbracelet/log.TestLogWithRaceCondition.func1()
      /home/yuguorui/Code/log/logger_test.go:230 +0x119
  testing.tRunner()
      /snap/go/10585/src/testing/testing.go:1689 +0x21e
  testing.(*T).Run.gowrap1()
      /snap/go/10585/src/testing/testing.go:1742 +0x44
==================
==================
WARNING: DATA RACE
Read at 0x00c000000300 by goroutine 21:
  github.com/charmbracelet/log.(*Logger).With()
      /home/yuguorui/Code/log/logger.go:331 +0x104
  github.com/charmbracelet/log.TestLogWithRaceCondition.func1.1()
      /home/yuguorui/Code/log/logger_test.go:224 +0x104

Previous write at 0x00c000000300 by goroutine 12:
  github.com/charmbracelet/log.(*Logger).With()
      /home/yuguorui/Code/log/logger.go:331 +0x116
  github.com/charmbracelet/log.TestLogWithRaceCondition.func1.2()
      /home/yuguorui/Code/log/logger_test.go:231 +0x10c

Goroutine 21 (running) created at:
  github.com/charmbracelet/log.TestLogWithRaceCondition.func1()
      /home/yuguorui/Code/log/logger_test.go:223 +0x215
  testing.tRunner()
      /snap/go/10585/src/testing/testing.go:1689 +0x21e
  testing.(*T).Run.gowrap1()
      /snap/go/10585/src/testing/testing.go:1742 +0x44

Goroutine 12 (finished) created at:
  github.com/charmbracelet/log.TestLogWithRaceCondition.func1()
      /home/yuguorui/Code/log/logger_test.go:230 +0x119
  testing.tRunner()
      /snap/go/10585/src/testing/testing.go:1689 +0x21e
  testing.(*T).Run.gowrap1()
      /snap/go/10585/src/testing/testing.go:1742 +0x44
==================
==================
WARNING: DATA RACE
Read at 0x00c0000003b0 by goroutine 21:
  github.com/charmbracelet/log.(*Logger).With()
      /home/yuguorui/Code/log/logger.go:332 +0x186
  github.com/charmbracelet/log.TestLogWithRaceCondition.func1.1()
      /home/yuguorui/Code/log/logger_test.go:224 +0x104

Previous write at 0x00c0000003b0 by goroutine 12:
  github.com/charmbracelet/log.(*Logger).With()
      /home/yuguorui/Code/log/logger.go:331 +0x116
  github.com/charmbracelet/log.TestLogWithRaceCondition.func1.2()
      /home/yuguorui/Code/log/logger_test.go:231 +0x10c

Goroutine 21 (running) created at:
  github.com/charmbracelet/log.TestLogWithRaceCondition.func1()
      /home/yuguorui/Code/log/logger_test.go:223 +0x215
  testing.tRunner()
      /snap/go/10585/src/testing/testing.go:1689 +0x21e
  testing.(*T).Run.gowrap1()
      /snap/go/10585/src/testing/testing.go:1742 +0x44

Goroutine 12 (finished) created at:
  github.com/charmbracelet/log.TestLogWithRaceCondition.func1()
      /home/yuguorui/Code/log/logger_test.go:230 +0x119
  testing.tRunner()
      /snap/go/10585/src/testing/testing.go:1689 +0x21e
  testing.(*T).Run.gowrap1()
      /snap/go/10585/src/testing/testing.go:1742 +0x44
==================
==================
WARNING: DATA RACE
Read at 0x00c000208300 by goroutine 21:
  github.com/charmbracelet/log.(*Logger).With()
      /home/yuguorui/Code/log/logger.go:332 +0x1a6
  github.com/charmbracelet/log.TestLogWithRaceCondition.func1.1()
      /home/yuguorui/Code/log/logger_test.go:224 +0x104

Previous write at 0x00c000208300 by goroutine 12:
  github.com/charmbracelet/log.(*Logger).With()
      /home/yuguorui/Code/log/logger.go:332 +0x1b5
  github.com/charmbracelet/log.TestLogWithRaceCondition.func1.2()
      /home/yuguorui/Code/log/logger_test.go:231 +0x10c

Goroutine 21 (running) created at:
  github.com/charmbracelet/log.TestLogWithRaceCondition.func1()
      /home/yuguorui/Code/log/logger_test.go:223 +0x215
  testing.tRunner()
      /snap/go/10585/src/testing/testing.go:1689 +0x21e
  testing.(*T).Run.gowrap1()
      /snap/go/10585/src/testing/testing.go:1742 +0x44

Goroutine 12 (finished) created at:
  github.com/charmbracelet/log.TestLogWithRaceCondition.func1()
      /home/yuguorui/Code/log/logger_test.go:230 +0x119
  testing.tRunner()
      /snap/go/10585/src/testing/testing.go:1689 +0x21e
  testing.(*T).Run.gowrap1()
      /snap/go/10585/src/testing/testing.go:1742 +0x44
==================
==================
WARNING: DATA RACE
Read at 0x00c000000390 by goroutine 21:
  github.com/charmbracelet/log.(*Logger).With()
      /home/yuguorui/Code/log/logger.go:337 +0x3b0
  github.com/charmbracelet/log.TestLogWithRaceCondition.func1.1()
      /home/yuguorui/Code/log/logger_test.go:224 +0x104

Previous write at 0x00c000000390 by goroutine 12:
  github.com/charmbracelet/log.(*Logger).With()
      /home/yuguorui/Code/log/logger.go:331 +0x116
  github.com/charmbracelet/log.TestLogWithRaceCondition.func1.2()
      /home/yuguorui/Code/log/logger_test.go:231 +0x10c

Goroutine 21 (running) created at:
  github.com/charmbracelet/log.TestLogWithRaceCondition.func1()
      /home/yuguorui/Code/log/logger_test.go:223 +0x215
  testing.tRunner()
      /snap/go/10585/src/testing/testing.go:1689 +0x21e
  testing.(*T).Run.gowrap1()
      /snap/go/10585/src/testing/testing.go:1742 +0x44

Goroutine 12 (finished) created at:
  github.com/charmbracelet/log.TestLogWithRaceCondition.func1()
      /home/yuguorui/Code/log/logger_test.go:230 +0x119
  testing.tRunner()
      /snap/go/10585/src/testing/testing.go:1689 +0x21e
  testing.(*T).Run.gowrap1()
      /snap/go/10585/src/testing/testing.go:1742 +0x44
==================
==================
WARNING: DATA RACE
Read at 0x00c00020a0c0 by goroutine 21:
  runtime.growslice()
      /snap/go/10585/src/runtime/slice.go:155 +0x0
  github.com/charmbracelet/log.(*Logger).With()
      /home/yuguorui/Code/log/logger.go:337 +0x3f2
  github.com/charmbracelet/log.TestLogWithRaceCondition.func1.1()
      /home/yuguorui/Code/log/logger_test.go:224 +0x104

Previous write at 0x00c00020a0c0 by goroutine 12:
  runtime.slicecopy()
      /snap/go/10585/src/runtime/slice.go:325 +0x0
  github.com/charmbracelet/log.(*Logger).With()
      /home/yuguorui/Code/log/logger.go:337 +0x45d
  github.com/charmbracelet/log.TestLogWithRaceCondition.func1.2()
      /home/yuguorui/Code/log/logger_test.go:231 +0x10c

Goroutine 21 (running) created at:
  github.com/charmbracelet/log.TestLogWithRaceCondition.func1()
      /home/yuguorui/Code/log/logger_test.go:223 +0x215
  testing.tRunner()
      /snap/go/10585/src/testing/testing.go:1689 +0x21e
  testing.(*T).Run.gowrap1()
      /snap/go/10585/src/testing/testing.go:1742 +0x44

Goroutine 12 (finished) created at:
  github.com/charmbracelet/log.TestLogWithRaceCondition.func1()
      /home/yuguorui/Code/log/logger_test.go:230 +0x119
  testing.tRunner()
      /snap/go/10585/src/testing/testing.go:1689 +0x21e
  testing.(*T).Run.gowrap1()
      /snap/go/10585/src/testing/testing.go:1742 +0x44
==================
==================
WARNING: DATA RACE
Read at 0x00c000000338 by goroutine 17:
  github.com/charmbracelet/log.(*Logger).With()
      /home/yuguorui/Code/log/logger.go:330 +0xcd
  github.com/charmbracelet/log.TestLogWithRaceCondition.func1.1()
      /home/yuguorui/Code/log/logger_test.go:224 +0x104

Previous write at 0x00c000000338 by goroutine 12:
  github.com/charmbracelet/log.(*Logger).With()
      /home/yuguorui/Code/log/logger.go:331 +0x116
  github.com/charmbracelet/log.TestLogWithRaceCondition.func1.2()
      /home/yuguorui/Code/log/logger_test.go:231 +0x10c

Goroutine 17 (running) created at:
  github.com/charmbracelet/log.TestLogWithRaceCondition.func1()
      /home/yuguorui/Code/log/logger_test.go:223 +0x215
  testing.tRunner()
      /snap/go/10585/src/testing/testing.go:1689 +0x21e
  testing.(*T).Run.gowrap1()
      /snap/go/10585/src/testing/testing.go:1742 +0x44

Goroutine 12 (finished) created at:
  github.com/charmbracelet/log.TestLogWithRaceCondition.func1()
      /home/yuguorui/Code/log/logger_test.go:230 +0x119
  testing.tRunner()
      /snap/go/10585/src/testing/testing.go:1689 +0x21e
  testing.(*T).Run.gowrap1()
      /snap/go/10585/src/testing/testing.go:1742 +0x44
==================
==================
WARNING: DATA RACE
Read at 0x00c0004180f8 by goroutine 22:
  github.com/charmbracelet/log.(*Logger).With()
      /home/yuguorui/Code/log/logger.go:330 +0xcd
  github.com/charmbracelet/log.TestLogWithRaceCondition.func1.2()
      /home/yuguorui/Code/log/logger_test.go:231 +0x10c

Previous write at 0x00c0004180f8 by goroutine 10:
  github.com/charmbracelet/log.(*Logger).With()
      /home/yuguorui/Code/log/logger.go:331 +0x116
  github.com/charmbracelet/log.TestLogWithRaceCondition.func1.2()
      /home/yuguorui/Code/log/logger_test.go:231 +0x10c

Goroutine 22 (running) created at:
  github.com/charmbracelet/log.TestLogWithRaceCondition.func1()
      /home/yuguorui/Code/log/logger_test.go:230 +0x119
  testing.tRunner()
      /snap/go/10585/src/testing/testing.go:1689 +0x21e
  testing.(*T).Run.gowrap1()
      /snap/go/10585/src/testing/testing.go:1742 +0x44

Goroutine 10 (finished) created at:
  github.com/charmbracelet/log.TestLogWithRaceCondition.func1()
      /home/yuguorui/Code/log/logger_test.go:230 +0x119
  testing.tRunner()
      /snap/go/10585/src/testing/testing.go:1689 +0x21e
  testing.(*T).Run.gowrap1()
      /snap/go/10585/src/testing/testing.go:1742 +0x44
==================
==================
WARNING: DATA RACE
Read at 0x00c000312000 by goroutine 26:
  github.com/charmbracelet/log.(*Logger).With()
      /home/yuguorui/Code/log/logger.go:331 +0x104
  github.com/charmbracelet/log.TestLogWithRaceCondition.func1.2()
      /home/yuguorui/Code/log/logger_test.go:231 +0x10c

Previous write at 0x00c000312000 by goroutine 20:
  github.com/charmbracelet/log.(*Logger).With()
      /home/yuguorui/Code/log/logger.go:331 +0x116
  github.com/charmbracelet/log.TestLogWithRaceCondition.func1.2()
      /home/yuguorui/Code/log/logger_test.go:231 +0x10c

Goroutine 26 (running) created at:
  github.com/charmbracelet/log.TestLogWithRaceCondition.func1()
      /home/yuguorui/Code/log/logger_test.go:230 +0x119
  testing.tRunner()
      /snap/go/10585/src/testing/testing.go:1689 +0x21e
  testing.(*T).Run.gowrap1()
      /snap/go/10585/src/testing/testing.go:1742 +0x44

Goroutine 20 (finished) created at:
  github.com/charmbracelet/log.TestLogWithRaceCondition.func1()
      /home/yuguorui/Code/log/logger_test.go:230 +0x119
  testing.tRunner()
      /snap/go/10585/src/testing/testing.go:1689 +0x21e
  testing.(*T).Run.gowrap1()
      /snap/go/10585/src/testing/testing.go:1742 +0x44
==================
==================
WARNING: DATA RACE
Read at 0x00c0003120b0 by goroutine 26:
  github.com/charmbracelet/log.(*Logger).With()
      /home/yuguorui/Code/log/logger.go:332 +0x186
  github.com/charmbracelet/log.TestLogWithRaceCondition.func1.2()
      /home/yuguorui/Code/log/logger_test.go:231 +0x10c

Previous write at 0x00c0003120b0 by goroutine 20:
  github.com/charmbracelet/log.(*Logger).With()
      /home/yuguorui/Code/log/logger.go:331 +0x116
  github.com/charmbracelet/log.TestLogWithRaceCondition.func1.2()
      /home/yuguorui/Code/log/logger_test.go:231 +0x10c

Goroutine 26 (running) created at:
  github.com/charmbracelet/log.TestLogWithRaceCondition.func1()
      /home/yuguorui/Code/log/logger_test.go:230 +0x119
  testing.tRunner()
      /snap/go/10585/src/testing/testing.go:1689 +0x21e
  testing.(*T).Run.gowrap1()
      /snap/go/10585/src/testing/testing.go:1742 +0x44

Goroutine 20 (finished) created at:
  github.com/charmbracelet/log.TestLogWithRaceCondition.func1()
      /home/yuguorui/Code/log/logger_test.go:230 +0x119
  testing.tRunner()
      /snap/go/10585/src/testing/testing.go:1689 +0x21e
  testing.(*T).Run.gowrap1()
      /snap/go/10585/src/testing/testing.go:1742 +0x44
==================
==================
WARNING: DATA RACE
Read at 0x00c00030e100 by goroutine 26:
  github.com/charmbracelet/log.(*Logger).With()
      /home/yuguorui/Code/log/logger.go:332 +0x1a6
  github.com/charmbracelet/log.TestLogWithRaceCondition.func1.2()
      /home/yuguorui/Code/log/logger_test.go:231 +0x10c

Previous write at 0x00c00030e100 by goroutine 20:
  github.com/charmbracelet/log.(*Logger).With()
      /home/yuguorui/Code/log/logger.go:332 +0x1b5
  github.com/charmbracelet/log.TestLogWithRaceCondition.func1.2()
      /home/yuguorui/Code/log/logger_test.go:231 +0x10c

Goroutine 26 (running) created at:
  github.com/charmbracelet/log.TestLogWithRaceCondition.func1()
      /home/yuguorui/Code/log/logger_test.go:230 +0x119
  testing.tRunner()
      /snap/go/10585/src/testing/testing.go:1689 +0x21e
  testing.(*T).Run.gowrap1()
      /snap/go/10585/src/testing/testing.go:1742 +0x44

Goroutine 20 (finished) created at:
  github.com/charmbracelet/log.TestLogWithRaceCondition.func1()
      /home/yuguorui/Code/log/logger_test.go:230 +0x119
  testing.tRunner()
      /snap/go/10585/src/testing/testing.go:1689 +0x21e
  testing.(*T).Run.gowrap1()
      /snap/go/10585/src/testing/testing.go:1742 +0x44
==================
==================
WARNING: DATA RACE
Read at 0x00c000312090 by goroutine 26:
  github.com/charmbracelet/log.(*Logger).With()
      /home/yuguorui/Code/log/logger.go:337 +0x3b0
  github.com/charmbracelet/log.TestLogWithRaceCondition.func1.2()
      /home/yuguorui/Code/log/logger_test.go:231 +0x10c

Previous write at 0x00c000312090 by goroutine 20:
  github.com/charmbracelet/log.(*Logger).With()
      /home/yuguorui/Code/log/logger.go:331 +0x116
  github.com/charmbracelet/log.TestLogWithRaceCondition.func1.2()
      /home/yuguorui/Code/log/logger_test.go:231 +0x10c

Goroutine 26 (running) created at:
  github.com/charmbracelet/log.TestLogWithRaceCondition.func1()
      /home/yuguorui/Code/log/logger_test.go:230 +0x119
  testing.tRunner()
      /snap/go/10585/src/testing/testing.go:1689 +0x21e
  testing.(*T).Run.gowrap1()
      /snap/go/10585/src/testing/testing.go:1742 +0x44

Goroutine 20 (finished) created at:
  github.com/charmbracelet/log.TestLogWithRaceCondition.func1()
      /home/yuguorui/Code/log/logger_test.go:230 +0x119
  testing.tRunner()
      /snap/go/10585/src/testing/testing.go:1689 +0x21e
  testing.(*T).Run.gowrap1()
      /snap/go/10585/src/testing/testing.go:1742 +0x44
==================
==================
WARNING: DATA RACE
Read at 0x00c000318040 by goroutine 26:
  runtime.growslice()
      /snap/go/10585/src/runtime/slice.go:155 +0x0
  github.com/charmbracelet/log.(*Logger).With()
      /home/yuguorui/Code/log/logger.go:337 +0x3f2
  github.com/charmbracelet/log.TestLogWithRaceCondition.func1.2()
      /home/yuguorui/Code/log/logger_test.go:231 +0x10c

Previous write at 0x00c000318040 by goroutine 20:
  runtime.slicecopy()
      /snap/go/10585/src/runtime/slice.go:325 +0x0
  github.com/charmbracelet/log.(*Logger).With()
      /home/yuguorui/Code/log/logger.go:337 +0x45d
  github.com/charmbracelet/log.TestLogWithRaceCondition.func1.2()
      /home/yuguorui/Code/log/logger_test.go:231 +0x10c

Goroutine 26 (running) created at:
  github.com/charmbracelet/log.TestLogWithRaceCondition.func1()
      /home/yuguorui/Code/log/logger_test.go:230 +0x119
  testing.tRunner()
      /snap/go/10585/src/testing/testing.go:1689 +0x21e
  testing.(*T).Run.gowrap1()
      /snap/go/10585/src/testing/testing.go:1742 +0x44

Goroutine 20 (finished) created at:
  github.com/charmbracelet/log.TestLogWithRaceCondition.func1()
      /home/yuguorui/Code/log/logger_test.go:230 +0x119
  testing.tRunner()
      /snap/go/10585/src/testing/testing.go:1689 +0x21e
  testing.(*T).Run.gowrap1()
      /snap/go/10585/src/testing/testing.go:1742 +0x44
==================
==================
WARNING: DATA RACE
Write at 0x00c0001120c8 by goroutine 26:
  github.com/charmbracelet/log.TestLogWithRaceCondition.func1.2()
      /home/yuguorui/Code/log/logger_test.go:231 +0x11e

Previous read at 0x00c0001120c8 by goroutine 27:
  github.com/charmbracelet/log.TestLogWithRaceCondition.func1.1()
      /home/yuguorui/Code/log/logger_test.go:224 +0xea

Goroutine 26 (running) created at:
  github.com/charmbracelet/log.TestLogWithRaceCondition.func1()
      /home/yuguorui/Code/log/logger_test.go:230 +0x119
  testing.tRunner()
      /snap/go/10585/src/testing/testing.go:1689 +0x21e
  testing.(*T).Run.gowrap1()
      /snap/go/10585/src/testing/testing.go:1742 +0x44

Goroutine 27 (running) created at:
  github.com/charmbracelet/log.TestLogWithRaceCondition.func1()
      /home/yuguorui/Code/log/logger_test.go:223 +0x215
  testing.tRunner()
      /snap/go/10585/src/testing/testing.go:1689 +0x21e
  testing.(*T).Run.gowrap1()
      /snap/go/10585/src/testing/testing.go:1742 +0x44
==================
==================
WARNING: DATA RACE
Write at 0x00c0001120c8 by goroutine 18:
  github.com/charmbracelet/log.TestLogWithRaceCondition.func1.2()
      /home/yuguorui/Code/log/logger_test.go:231 +0x11e

Previous read at 0x00c0001120c8 by goroutine 22:
  github.com/charmbracelet/log.TestLogWithRaceCondition.func1.2()
      /home/yuguorui/Code/log/logger_test.go:232 +0x15a

Goroutine 18 (running) created at:
  github.com/charmbracelet/log.TestLogWithRaceCondition.func1()
      /home/yuguorui/Code/log/logger_test.go:230 +0x119
  testing.tRunner()
      /snap/go/10585/src/testing/testing.go:1689 +0x21e
  testing.(*T).Run.gowrap1()
      /snap/go/10585/src/testing/testing.go:1742 +0x44

Goroutine 22 (running) created at:
  github.com/charmbracelet/log.TestLogWithRaceCondition.func1()
      /home/yuguorui/Code/log/logger_test.go:230 +0x119
  testing.tRunner()
      /snap/go/10585/src/testing/testing.go:1689 +0x21e
  testing.(*T).Run.gowrap1()
      /snap/go/10585/src/testing/testing.go:1742 +0x44
==================
==================
WARNING: DATA RACE
Write at 0x00c00028e2c0 by goroutine 31:
  runtime.slicecopy()
      /snap/go/10585/src/runtime/slice.go:325 +0x0
  github.com/charmbracelet/log.(*Logger).With()
      /home/yuguorui/Code/log/logger.go:337 +0x45d
  github.com/charmbracelet/log.TestLogWithRaceCondition.func1.1()
      /home/yuguorui/Code/log/logger_test.go:224 +0x104

Previous write at 0x00c00028e2c0 by goroutine 30:
  runtime.slicecopy()
      /snap/go/10585/src/runtime/slice.go:325 +0x0
  github.com/charmbracelet/log.(*Logger).With()
      /home/yuguorui/Code/log/logger.go:337 +0x45d
  github.com/charmbracelet/log.TestLogWithRaceCondition.func1.2()
      /home/yuguorui/Code/log/logger_test.go:231 +0x10c

Goroutine 31 (running) created at:
  github.com/charmbracelet/log.TestLogWithRaceCondition.func1()
      /home/yuguorui/Code/log/logger_test.go:223 +0x215
  testing.tRunner()
      /snap/go/10585/src/testing/testing.go:1689 +0x21e
  testing.(*T).Run.gowrap1()
      /snap/go/10585/src/testing/testing.go:1742 +0x44

Goroutine 30 (finished) created at:
  github.com/charmbracelet/log.TestLogWithRaceCondition.func1()
      /home/yuguorui/Code/log/logger_test.go:230 +0x119
  testing.tRunner()
      /snap/go/10585/src/testing/testing.go:1689 +0x21e
  testing.(*T).Run.gowrap1()
      /snap/go/10585/src/testing/testing.go:1742 +0x44
==================
==================
WARNING: DATA RACE
Write at 0x00c000396180 by goroutine 46:
  runtime.slicecopy()
      /snap/go/10585/src/runtime/slice.go:325 +0x0
  github.com/charmbracelet/log.(*Logger).With()
      /home/yuguorui/Code/log/logger.go:337 +0x45d
  github.com/charmbracelet/log.TestLogWithRaceCondition.func1.2()
      /home/yuguorui/Code/log/logger_test.go:231 +0x10c

Previous write at 0x00c000396180 by goroutine 44:
  runtime.slicecopy()
      /snap/go/10585/src/runtime/slice.go:325 +0x0
  github.com/charmbracelet/log.(*Logger).With()
      /home/yuguorui/Code/log/logger.go:337 +0x45d
  github.com/charmbracelet/log.TestLogWithRaceCondition.func1.2()
      /home/yuguorui/Code/log/logger_test.go:231 +0x10c

Goroutine 46 (running) created at:
  github.com/charmbracelet/log.TestLogWithRaceCondition.func1()
      /home/yuguorui/Code/log/logger_test.go:230 +0x119
  testing.tRunner()
      /snap/go/10585/src/testing/testing.go:1689 +0x21e
  testing.(*T).Run.gowrap1()
      /snap/go/10585/src/testing/testing.go:1742 +0x44

Goroutine 44 (running) created at:
  github.com/charmbracelet/log.TestLogWithRaceCondition.func1()
      /home/yuguorui/Code/log/logger_test.go:230 +0x119
  testing.tRunner()
      /snap/go/10585/src/testing/testing.go:1689 +0x21e
  testing.(*T).Run.gowrap1()
      /snap/go/10585/src/testing/testing.go:1742 +0x44
==================
==================
WARNING: DATA RACE
Write at 0x00c000420248 by goroutine 53:
  runtime.slicecopy()
      /snap/go/10585/src/runtime/slice.go:325 +0x0
  github.com/charmbracelet/log.(*Logger).With()
      /home/yuguorui/Code/log/logger.go:337 +0x45d
  github.com/charmbracelet/log.TestLogWithRaceCondition.func1.1()
      /home/yuguorui/Code/log/logger_test.go:224 +0x104

Previous write at 0x00c000420248 by goroutine 51:
  runtime.slicecopy()
      /snap/go/10585/src/runtime/slice.go:325 +0x0
  github.com/charmbracelet/log.(*Logger).With()
      /home/yuguorui/Code/log/logger.go:337 +0x45d
  github.com/charmbracelet/log.TestLogWithRaceCondition.func1.1()
      /home/yuguorui/Code/log/logger_test.go:224 +0x104

Goroutine 53 (running) created at:
  github.com/charmbracelet/log.TestLogWithRaceCondition.func1()
      /home/yuguorui/Code/log/logger_test.go:223 +0x215
  testing.tRunner()
      /snap/go/10585/src/testing/testing.go:1689 +0x21e
  testing.(*T).Run.gowrap1()
      /snap/go/10585/src/testing/testing.go:1742 +0x44

Goroutine 51 (finished) created at:
  github.com/charmbracelet/log.TestLogWithRaceCondition.func1()
      /home/yuguorui/Code/log/logger_test.go:223 +0x215
  testing.tRunner()
      /snap/go/10585/src/testing/testing.go:1689 +0x21e
  testing.(*T).Run.gowrap1()
      /snap/go/10585/src/testing/testing.go:1742 +0x44
==================
==================
WARNING: DATA RACE
Write at 0x00c0001120c8 by goroutine 84:
  github.com/charmbracelet/log.TestLogWithRaceCondition.func1.2()
      /home/yuguorui/Code/log/logger_test.go:231 +0x11e

Previous write at 0x00c0001120c8 by goroutine 86:
  github.com/charmbracelet/log.TestLogWithRaceCondition.func1.2()
      /home/yuguorui/Code/log/logger_test.go:231 +0x11e

Goroutine 84 (running) created at:
  github.com/charmbracelet/log.TestLogWithRaceCondition.func1()
      /home/yuguorui/Code/log/logger_test.go:230 +0x119
  testing.tRunner()
      /snap/go/10585/src/testing/testing.go:1689 +0x21e
  testing.(*T).Run.gowrap1()
      /snap/go/10585/src/testing/testing.go:1742 +0x44

Goroutine 86 (finished) created at:
  github.com/charmbracelet/log.TestLogWithRaceCondition.func1()
      /home/yuguorui/Code/log/logger_test.go:230 +0x119
  testing.tRunner()
      /snap/go/10585/src/testing/testing.go:1689 +0x21e
  testing.(*T).Run.gowrap1()
      /snap/go/10585/src/testing/testing.go:1742 +0x44
==================
==================
WARNING: DATA RACE
Read at 0x00c000312948 by goroutine 146:
  sync/atomic.LoadInt32()
      /snap/go/10585/src/runtime/race_amd64.s:202 +0xb
  sync/atomic.LoadUint32()
      <autogenerated>:1 +0x10
  github.com/charmbracelet/log.(*Logger).Info()
      /home/yuguorui/Code/log/logger.go:356 +0x184
  github.com/charmbracelet/log.TestLogWithRaceCondition.func1.2()
      /home/yuguorui/Code/log/logger_test.go:232 +0x156

Previous write at 0x00c000312948 by goroutine 160:
  github.com/charmbracelet/log.(*Logger).With()
      /home/yuguorui/Code/log/logger.go:331 +0x116
  github.com/charmbracelet/log.TestLogWithRaceCondition.func1.2()
      /home/yuguorui/Code/log/logger_test.go:231 +0x10c

Goroutine 146 (running) created at:
  github.com/charmbracelet/log.TestLogWithRaceCondition.func1()
      /home/yuguorui/Code/log/logger_test.go:230 +0x119
  testing.tRunner()
      /snap/go/10585/src/testing/testing.go:1689 +0x21e
  testing.(*T).Run.gowrap1()
      /snap/go/10585/src/testing/testing.go:1742 +0x44

Goroutine 160 (running) created at:
  github.com/charmbracelet/log.TestLogWithRaceCondition.func1()
      /home/yuguorui/Code/log/logger_test.go:230 +0x119
  testing.tRunner()
      /snap/go/10585/src/testing/testing.go:1689 +0x21e
  testing.(*T).Run.gowrap1()
      /snap/go/10585/src/testing/testing.go:1742 +0x44
==================
    testing.go:1398: race detected during execution of test
--- FAIL: TestLogWithRaceCondition (0.00s)
    --- FAIL: TestLogWithRaceCondition/must_be_run_with_-race (0.00s)
FAIL
FAIL    github.com/charmbracelet/log    0.019s
FAIL
yuguorui commented 6 months ago

Please pay primary attention to this section in the above back-trace.

WARNING: DATA RACE
Write at 0x00c000396180 by goroutine 46:
  runtime.slicecopy()
      /snap/go/10585/src/runtime/slice.go:325 +0x0
  github.com/charmbracelet/log.(*Logger).With()
      /home/yuguorui/Code/log/logger.go:337 +0x45d
  github.com/charmbracelet/log.TestLogWithRaceCondition.func1.2()
      /home/yuguorui/Code/log/logger_test.go:231 +0x10c

And here is the logger.go:337 is doing. https://github.com/charmbracelet/log/blob/77a8113c38339f95e0e2ba68ffa1c46a133f2227/logger.go#L328-L340

aymanbagabas commented 6 months ago

Looks like the go test -race in coverage is failing

yuguorui commented 6 months ago 
$ git checkout -
Previous HEAD position was 53ace56 fix(test): use sublogger generated from With() in race detection
Switched to branch 'main'
Your branch is ahead of 'origin/main' by 2 commits.
  (use "git push" to publish your local commits)

# yuguorui @ yuguorui-ubt in ~/Code/log on git:main x [6:33:22]
$ go test -race ./...
ok      github.com/charmbracelet/log    (cached)

# yuguorui @ yuguorui-ubt in ~/Code/log on git:main x [6:33:24]
$ git checkout -
Note: switching to '53ace56f7d85792cccdac948e6cd34839de10908'.

# yuguorui @ yuguorui-ubt in ~/Code/log on git:53ace56 x [6:33:33]
$ go test -race ./...
==================
WARNING: DATA RACE
Write at 0x00c00032fd08 by goroutine 110:
  runtime.slicecopy()
      /snap/go/10585/src/runtime/slice.go:325 +0x0
  github.com/charmbracelet/log.(*Logger).With()
      /home/yuguorui/Code/log/logger.go:337 +0x45d
  github.com/charmbracelet/log.TestLogWithRaceCondition.func1.1()
      /home/yuguorui/Code/log/logger_test.go:231 +0x104

Previous write at 0x00c00032fd08 by goroutine 104:
  runtime.slicecopy()
      /snap/go/10585/src/runtime/slice.go:325 +0x0
  github.com/charmbracelet/log.(*Logger).With()
      /home/yuguorui/Code/log/logger.go:337 +0x45d
  github.com/charmbracelet/log.TestLogWithRaceCondition.func1.1()
      /home/yuguorui/Code/log/logger_test.go:231 +0x104

Goroutine 110 (running) created at:
  github.com/charmbracelet/log.TestLogWithRaceCondition.func1()
      /home/yuguorui/Code/log/logger_test.go:230 +0x595
  testing.tRunner()
      /snap/go/10585/src/testing/testing.go:1689 +0x21e
  testing.(*T).Run.gowrap1()
      /snap/go/10585/src/testing/testing.go:1742 +0x44

Goroutine 104 (finished) created at:
  github.com/charmbracelet/log.TestLogWithRaceCondition.func1()
      /home/yuguorui/Code/log/logger_test.go:230 +0x595
  testing.tRunner()
      /snap/go/10585/src/testing/testing.go:1689 +0x21e
  testing.(*T).Run.gowrap1()
      /snap/go/10585/src/testing/testing.go:1742 +0x44
==================
--- FAIL: TestLogWithRaceCondition (0.01s)
    --- FAIL: TestLogWithRaceCondition/must_be_run_with_-race (0.01s)
        testing.go:1398: race detected during execution of test
FAIL
FAIL    github.com/charmbracelet/log    0.089s
FAIL
yuguorui commented 6 months ago

Sorry, two reasons for here.

  1. The long args are necessary.

    +                       longArgs := make([]interface{}, 0, 1000)
+                       for i := 0; i < 1000; i++ {
+                               longArgs = append(longArgs, fmt.Sprintf("arg%d", i), fmt.Sprintf("val%d", i))
+                       }
+                       l = l.With(longArgs...)

  2. Override the l in the testing goroutine is racy..., so we need to remove it. Sorry again.

                                go func() {
-                                       l = l.With("arg1", "val1", "arg2", "val2")
                                    l.Info("kinda long log message")
                                    done.Done()
                            }()