fix: deep copy the fields to avoid data race #128
Merged
+24
−13
Conversation
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
yuguorui
force-pushed
the
main
branch
2 times, most recently
from
a140135 to
ec7c8c2
Compare
Codecov ReportAll modified and coverable lines are covered by tests ✅
Additional details and impacted files@@ 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 ☔ View full report in Codecov by Sentry. |
|
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. |
|
Kindly ping again~ |
|
@yuguorui I can't trigger the test case using |
|
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. |
|
Please pay primary attention to this section in the above back-trace. And here is the logger.go:337 is doing. Lines 328 to 340 in 77a8113 |
|
Looks like the |
The new sublogger generated from With() are never used, which may cause optimization of the sublogger, and no race condition is detected. Use a for loop to spawn a lots of goroutines to ensure the race condition would happen in CI. We also need to replace the bytes.Buffer to io.Discard, since the bytes.Buffer is also not thread-safe. Signed-off-by: yuguorui <yuguorui@pku.edu.cn>
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. Signed-off-by: yuguorui <yuguorui@pku.edu.cn>
$ 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 |
|
Sorry, two reasons for here.
+ 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...)
go func() {
- l = l.With("arg1", "val1", "arg2", "val2")
l.Info("kinda long log message")
done.Done()
}() |
aymanbagabas
approved these changes
May 14, 2024
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.
This suggestion is invalid because no changes were made to the code.
Suggestions cannot be applied while the pull request is closed.
Suggestions cannot be applied while viewing a subset of changes.
Only one suggestion per line can be applied in a batch.
Add this suggestion to a batch that can be applied as a single commit.
Applying suggestions on deleted lines is not supported.
You must change the existing code in this line in order to create a valid suggestion.
Outdated suggestions cannot be applied.
This suggestion has been applied or marked resolved.
Suggestions cannot be applied from pending reviews.
Suggestions cannot be applied on multi-line comments.
Suggestions cannot be applied while the pull request is queued to merge.
Suggestion cannot be applied right now. Please check back later.
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.