slog/log: Concurrent writes to TextHandler and JSONHandler lose log lines.

[WillAbides]

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

$ go version
go version go1.21rc2 darwin/amd64

Does this issue reproduce with the latest release?

It reproduces on go1.21rc2, and on go1.20 if I use "golang.org/x/exp/slog"
instead of "log/slog"

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

go env Output

$ go env
GO111MODULE='on'
GOARCH='amd64'
GOBIN=''
GOCACHE='/Users/wroden/Library/Caches/go-build'
GOENV='/Users/wroden/Library/Application Support/go/env'
GOEXE=''
GOEXPERIMENT=''
GOFLAGS=''
GOHOSTARCH='amd64'
GOHOSTOS='darwin'
GOINSECURE=''
GOMODCACHE='/Users/wroden/go/pkg/mod'
GONOPROXY=''
GONOSUMDB=''
GOOS='darwin'
GOPATH='/Users/wroden/go'
GOPRIVATE=''
GOPROXY='https://proxy.golang.org,direct'
GOROOT='/Users/wroden/go/go1.21rc2'
GOSUMDB='sum.golang.org'
GOTMPDIR=''
GOTOOLCHAIN='auto'
GOTOOLDIR='/Users/wroden/go/go1.21rc2/pkg/tool/darwin_amd64'
GOVCS=''
GOVERSION='go1.21rc2'
GCCGO='gccgo'
GOAMD64='v1'
AR='ar'
CC='clang'
CXX='clang++'
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 -arch x86_64 -m64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -ffile-prefix-map=/var/folders/bm/vj4qgj_n737bj6l4b2wkf08h0000gn/T/go-build3015726571=/tmp/go-build -gno-record-gcc-switches -fno-common'

What did you do?

I logged a lot of messages from concurrent goroutines to a slog.Logger and children
created by logger.With(...). See the play link for more details.

play: https://go.dev/play/p/Uhzxkd5e-a7?v=gotip

What did you expect to see?

I expected to see all the logged messages in the logger's output.

What did you see instead?

Most of the logged messages, but not all of them.

The only way I could get it to reliably log all messages was to use one mutex for all the loggers. Separate mutexes for each child logger did not help.

What else?

To check whether this was a problem with the handler or the logger, I also tried
calling handler.Handle() directly. That showed the problem is in the handler
and happens on both of the handlers provided by the slog package.

In experimenting with dummy handlers, the only way I found to avoid this is
adding a mutex to the handler. I'm not sure if that's the best solution, but it
does seem to work.

[AndrewHarrisSPU]

The test is racing. The counts get a little better with wg.Add(count) rather than invoking wg.Add(1) but there's more to it - I am a bit rushed and can't dig into why the test is racing (I think it's racing buffer writes?) but it seems like it would be worth fixing that to see if the problem persists.

[bcmills]

(attn @jba)

[WillAbides]

@AndrewHarrisSPU I agree that there is a race writing to buf, but I think it's the handler's responsibility to guard against that race.

The doc says:

// Any of the Handler's methods may be called concurrently with itself
// or with other methods. It is the responsibility of the Handler to
// manage this concurrency.

commonHandler already has a mutex guarding against concurrent writes to the output. It just doesn't extend that to child handlers.

[jba]

Thanks everyone. 20 seconds after reading "it just doesn't extend that to child handlers" I realized there was a serious bug, which I hadn't noticed in many months of development.

To elaborate on what @WillAbides said, the handler implementation has two fields, a sync.Mutex and an io.Writer, with the first protecting the second. Every call with Handler.WithGroup and Handler.WithAttrs creates a clone of that handler with additional information. The clone has a new mutex, but the same io.Writer.

One fix is to change the sync.Mutex field to a *sync.Mutex.
Another is to write a lockingWriter type that holds both the mutex and the io.Writer, and pass a pointer to that around.
I think they're basically the same thing. Does anyone see a difference? Does anyone have a preference?

[WillAbides]

@jba I've been fiddling with it here and got it working by changing mu to a sync.Locker and updating NewTextHandler, NewJSONHandler and newDefaultHandler to set it with mu: &sync.Mutex{}. Then update commonHandler.clone() to set mu and defaultHandler.Handle to use the lock. I think that's all the production changes necessary for this.

I would be happy to submit a change.

[jba]

Yeah, that's my option 1.

Would love to take your change! Thanks!
But just write *sync.Mutex, not sync.Locker. (Unless you see a problem with that?)
And please turn your play link into a test, if you don't mind.

[WillAbides]

Will do. I'll have something pushed shortly.

[jba]

This is still going to be a problem for people who make two top-level loggers that use the same io.Writer. I don't think there's a simple fix for that. (The log package has the same problem, if I'm not mistaken.)

We ultimately want something like zapcore.Lock, that does my option 2: wraps an io.Writer in a lock. Maybe I'll propose that once the dust settles.

/cc @bcmills

[gopherbot]

Change https://go.dev/cl/509196 mentions this issue: log/slog: fix issue with concurrent writes

[AndrewHarrisSPU]

Seems good to have caught this :)

This is still going to be a problem for people who make two top-level loggers that use the same io.Writer. I don't think there's a simple fix for that. (The log package has the same problem, if I'm not mistaken.)

We ultimately want something like zapcore.Lock, that does my option 2: wraps an io.Writer in a lock. Maybe I'll propose that once the dust settles.

/cc @bcmills

I wonder about an additional WriterAlreadySynchronizes boolean field of slog.HandlerOptions, which could indicate the writer is trusted when set true and subsequently not invoke the mutex in the common handler. This might be a way to permit something like zerolog's lock-free/atomic diodes - I don't know if many people actually need this, but it was interesting.

[bcmills]

The documentation for (*TextHandler).Handle and (*JSONHandler).Handle requires that each Record is written as a single call to Write. So for multiple top-level loggers that use the same io.Writer, it should suffice to wrap the Write method to acquire and release a mutex.