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.

(attn @jba)

@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.

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?

@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.

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.

Will do. I'll have something pushed shortly.

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

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

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.

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.