Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

log/slog: data race in log/slog.Logger.With #63225

Closed
limpo1989 opened this issue Sep 26, 2023 · 2 comments
Closed

log/slog: data race in log/slog.Logger.With #63225

limpo1989 opened this issue Sep 26, 2023 · 2 comments
Labels
NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.

Comments

@limpo1989
Copy link

What version of Go are you using (go version)?

$ go version
go version go1.21.1 linux/amd64

Does this issue reproduce with the latest release?

Yes

What operating system and processor architecture are you using (go env)?

go env Output
$ go env
GO111MODULE=''
GOARCH='amd64'
GOBIN=''
GOCACHE='/home/limpo1989/.cache/go-build'
GOENV='/home/limpo1989/.config/go/env'
GOEXE=''
GOEXPERIMENT=''
GOFLAGS=''
GOHOSTARCH='amd64'
GOHOSTOS='linux'
GOINSECURE=''
GOMODCACHE='/home/limpo1989/go/pkg/mod'
GOOS='linux'
GOPATH='/home/limpo1989/go'
GOROOT='/usr/local/go'
GOSUMDB='sum.golang.org'
GOTMPDIR=''
GOTOOLCHAIN='auto'
GOTOOLDIR='/usr/local/go/pkg/tool/linux_amd64'
GOVCS=''
GOVERSION='go1.21.1'
GCCGO='gccgo'
GOAMD64='v1'
AR='ar'
CC='gcc'
CXX='g++'
CGO_ENABLED='1'
GOMOD='/dev/null'
GOWORK=''
CGO_CFLAGS='-O2 -g'
CGO_CPPFLAGS=''
CGO_CXXFLAGS='-O2 -g'
CGO_FFLAGS='-O2 -g'
CGO_LDFLAGS='-O2 -g'
PKG_CONFIG='pkg-config'
GOGCCFLAGS='-fPIC -m64 -pthread -Wl,--no-gc-sections -fmessage-length=0 -ffile-prefix-map=/tmp/go-build3114110366=/tmp/go-build -gno-record-gcc-switches'

What did you do?

In the slog logging library, I use With to create a new log copy, which makes it easier to add independent loggers in different modules.
https://pkg.go.dev/log/slog#Logger.With

The test program reports a DATA RACE. What should I do?

What did you expect to see?

The test passed.

What did you see instead?

Run unit test command, and added the -race argument. The test failed.

==================
WARNING: DATA RACE
Read at 0x00c0001dc130 by goroutine 24:
  log/slog.(*commonHandler).enabled()
      /usr/local/go/src/log/slog/handler.go:218 +0x51
  log/slog.(*TextHandler).Enabled()
      /usr/local/go/src/log/slog/text_handler.go:45 +0x26
  log/slog.(*Logger).Enabled()
      /usr/local/go/src/log/slog/logger.go:137 +0x75
  log/slog.(*Logger).log()
      /usr/local/go/src/log/slog/logger.go:210 +0x96
  log/slog.(*Logger).Info()
      /usr/local/go/src/log/slog/logger.go:178 +0x11e
  github.com/go-spring-projects/go-spring/gs.(*App).Shutdown()
      /mnt/e/projects/go-spring-projects/go-spring/gs/app.go:189 +0x72
  github.com/go-spring-projects/go-spring/gs.TestConfig.func3.2()
      /mnt/e/projects/go-spring-projects/go-spring/gs/app_test.go:80 +0x5b
  runtime.deferreturn()
      /usr/local/go/src/runtime/panic.go:477 +0x30
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:1595 +0x238
  testing.(*T).Run.func1()
      /usr/local/go/src/testing/testing.go:1648 +0x44

Previous write at 0x00c0001dc130 by goroutine 25:
  log/slog.(*commonHandler).clone()
      /usr/local/go/src/log/slog/handler.go:204 +0x4cf
  log/slog.(*commonHandler).withAttrs()
      /usr/local/go/src/log/slog/handler.go:230 +0x3d4
  log/slog.(*TextHandler).WithAttrs()
      /usr/local/go/src/log/slog/text_handler.go:51 +0x57
  log/slog.(*Logger).With()
      /usr/local/go/src/log/slog/logger.go:99 +0x112
  github.com/go-spring-projects/go-spring/internal/log.GetLogger()
      /mnt/e/projects/go-spring-projects/go-spring/internal/log/logger.go:74 +0x187
  github.com/go-spring-projects/go-spring/gs.GetLogger()
      /mnt/e/projects/go-spring-projects/go-spring/gs/logger.go:28 +0x4dc
  github.com/go-spring-projects/go-spring/gs.(*App).run()
      /mnt/e/projects/go-spring-projects/go-spring/gs/app.go:91 +0x4ba
  github.com/go-spring-projects/go-spring/gs.(*App).Run()
      /mnt/e/projects/go-spring-projects/go-spring/gs/app.go:68 +0xa9
  github.com/go-spring-projects/go-spring/gs.startApplication.func2()
      /mnt/e/projects/go-spring-projects/go-spring/gs/app_test.go:40 +0x35

Full Report:
https://github.com/go-spring-projects/go-spring/actions/runs/6307172009/job/17123387313#step:4:80
@ianlancetaylor
Copy link
Contributor

CC @jba

@thanm thanm added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Sep 26, 2023
@seankhliao
Copy link
Member

seankhliao commented Sep 27, 2023 •
edited

This is a race in your test setup, you call app.Run in goroutine which sets your loggger, unsynchronized with app.Shutdown which calls it.

simplified as https://go.dev/play/p/piG5pNjWGsw

@seankhliao seankhliao closed this as not planned Won't fix, can't repro, duplicate, stale Sep 27, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
4 participants
@ianlancetaylor @limpo1989 @seankhliao @thanm