fatal error: concurrent map iteration and map write

[dpup]

We experienced a crash today that I'm having trouble diagnosing. The error occurred when calling logger.Info inside a goroutine. There were several parallel tasks, all which log when they complete. This code has been running, unchanged for months and I don't believe we've had any issues before.

Are logger.WithField and logger.WithError intended to be threadsafe?

Thanks in advance.

---

The error occurs at line 155 in (e *Entry) mergedFields

151 func (e *Entry) mergedFields() Fields {
152     f := Fields{}
153 
154     for _, fields := range e.fields {
155         for k, v := range fields {
156             f[k] = v
157         }
158     }
159
160     return f
161 }

/usr/lib/golang/src/runtime/panic.go:617 +0x72 fp=0xc001167d48 sp=0xc001167d18 pc=0x43a112
runtime.mapiternext(0xc001167e28)
/usr/lib/golang/src/runtime/map.go:860 +0x597 fp=0xc001167dd0 sp=0xc001167d48 pc=0x41ccd7
vendor/github.com/apex/log.(*Entry).mergedFields(0xc00017d260, 0x14)
/go/src/vendor/github.com/apex/log/entry.go:155 +0x6c fp=0xc001167e98 sp=0xc001167dd0 pc=0x77aeac
vendor/github.com/apex/log.(*Entry).finalize(0xc00017d260, 0x1, 0x1779ed3, 0x1c, 0x0)
/go/src/vendor/github.com/apex/log/entry.go:167 +0x2f fp=0xc001167ee0 sp=0xc001167e98 pc=0x77afef
vendor/github.com/apex/log.(*Logger).log(0x2978830, 0x1, 0xc00017d260, 0x1779ed3, 0x1c)
/go/src/vendor/github.com/apex/log/logger.go:146 +0x5c fp=0xc001167f28 sp=0xc001167ee0 pc=0x77c31c
vendor/github.com/apex/log.(*Entry).Info(...)

[tj]

hmm yea definitely should be, sounds like a bug to me, thanks for reporting!

[dpup]

Just an FYI that we're seeing this regularly now. A refinement on the original data, the code is essentially calling logger.Info("...") from multiple goroutines.

[seanami]

I have some more info about how this bug occurs:

• We have a function that calls logger.WithFields(fields) in order to create the logger instance that is shared between multiple goroutines.
• Calls to logger.Info(...) may then run concurrently with other code that writes additional keys/values to that fields instance.
• Since fields is a log.Fields, which is implemented with a map underneath, if a read and a write collide, we can get this error. It's not safe to concurrently read from and write to a map (as I learned today while investigating this).

We can address this in our own code by ensuring that fields is never written to after it's used to make a logger (by copying it).

But I wonder if it would also make sense to prevent this type of mistake at the apex/log level?

• Perhaps func (f Fields) Fields() Fields should make a shallow copy of the underlying map instead of just returning the Fields struct?
• Or perhaps func (e *Entry) WithFields(fields Fielder) *Entry should make a copy of fields.Fields() before appending it to the list of fields objects?

Either of those options would ensure that no further writes to a fields map can occur that would be concurrent with a call to log something.

[bertzzie]

Hi, opening a PR to fix the issue, please let me know if there's anything to improve there :)