Race condition in entry.Data on calling WithFields() method

[oshankkumar]

fatal error: concurrent map iteration and map write
runtime.mapiternext(0xc000bbee98)
	/usr/local/go/src/runtime/map.go:858 +0x579 fp=0xc000bbedd8 sp=0xc000bbed50 pc=0x1011289
vendor/github.com/sirupsen/logrus.(*Entry).WithFields(0xc0001065b0, 0xc0009d3f50, 0xc0009d3f50)
	vendor/github.com/sirupsen/logrus/entry.go:117 +0xef fp=0xc000bbef08 sp=0xc000bbedd8 pc=0x1479b0f```

[freeformz]

What version of logrus are you using?
Any chance we could get the full output of the trace?

[lwsanty]

@oshankkumar could you please check it on PR branch #1047 ?
Had a similar issue today and my fix helped

[lagren]

I'm experiencing the same issue with logrus v1.4.2.

I did not manage to get a full output of the trace (Stackdriver removes formatting and is not very good at exporting ad-hoc logs), but I did manage to get the parts that are touching logrus code:

goroutine 88 [running]:
github.com/sirupsen/logrus.(*Entry).WithFields(0xc000160700, 0xc00049d7c8, 0xd8f735)
/go/pkg/mod/github.com/sirupsen/logrus@v1.4.2/entry.go:117 +0xdc fp=0xc00049d660 sp=0xc00049d530 pc=0x7b892c

goroutine 86 [runnable]:
github.com/sirupsen/logrus.(*Entry).write(0xc000155ea0)
/go/pkg/mod/github.com/sirupsen/logrus@v1.4.2/entry.go:255 +0xa1
github.com/sirupsen/logrus.Entry.log(0xc000160540, 0xc000693f20, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
/go/pkg/mod/github.com/sirupsen/logrus@v1.4.2/entry.go:231 +0x19d
github.com/sirupsen/logrus.(*Entry).Log(0xc000160700, 0x4, 0xc00069dc10, 0x1, 0x1)
/go/pkg/mod/github.com/sirupsen/logrus@v1.4.2/entry.go:268 +0xeb
github.com/sirupsen/logrus.(*Entry).Logf(0xc000160700, 0xc000000004, 0xda9c39, 0x25, 0x0, 0x0, 0x0)
/go/pkg/mod/github.com/sirupsen/logrus@v1.4.2/entry.go:314 +0xe2
github.com/sirupsen/logrus.(*Entry).Infof(...)
/go/pkg/mod/github.com/sirupsen/logrus@v1.4.2/entry.go:327

goroutine 86 is sending the log entry to a custom formatter and I'm goint to take a look on how it is using the Entry.Data map

[dgsb]

@oshankkumar do you use any hooks which could modify the Data map of the entry ?

[limingyao]

@oshankkumar do you use any hooks which could modify the Data map of the entry ?

how to fix, if use hooks which could modify the Data map of the entry

[mrobinsn]

We had success using #1047, stopped the panics for us.

[bconway]

Seeing the same panic on 1.4.2 with use of Entry.

Edit: Actually, I misspoke. I'm seeing a different map range issue here:

https://github.com/sirupsen/logrus/blob/v1.4.2/text_formatter.go#L109

[markphelps]

Going to re-open this since the #1047 caused deadlocks, so we are reverting #1047

We need to find a better solution to fix this issue than locking the Logger mutex

[marwan-at-work]

@oshankkumar (or anyone else) can you please provide some code that reproduces this issue in logrus@v1.4.2? I'm unable to reproduce it, thanks

[bconway]

I tried to write up a test that fails with the use of Entry + hooks, but I think my lack of a working local environment to receive the hook has slowed me down. Here's a stack trace from 6 days ago in production, slightly cleaned:

runtime.errorString: runtime error: invalid memory address or nil pointer dereference
  File "/usr/local/go/src/runtime/signal_unix.go", line 695, in sigpanic
  File "/go/src/github.com/blocknonip/myplatform/vendor/github.com/sirupsen/logrus/text_formatter.go", line 316, in appendValue
  File "/go/src/github.com/blocknonip/myplatform/vendor/github.com/sirupsen/logrus/text_formatter.go", line 312, in appendKeyValue
  File "/go/src/github.com/blocknonip/myplatform/vendor/github.com/sirupsen/logrus/text_formatter.go", line 216, in Format
  File "/go/src/github.com/blocknonip/myplatform/vendor/github.com/sirupsen/logrus/entry.go", line 277, in write
  File "/go/src/github.com/blocknonip/myplatform/vendor/github.com/sirupsen/logrus/entry.go", line 253, in log
  File "/go/src/github.com/blocknonip/myplatform/vendor/github.com/sirupsen/logrus/entry.go", line 289, in Log
  File "/go/src/github.com/blocknonip/myplatform/vendor/github.com/sirupsen/logrus/entry.go", line 335, in Logf
  File "/go/src/github.com/blocknonip/myplatform/apps/myapp/streamer.go", line 652, in sendStream
  File "/go/src/github.com/blocknonip/myplatform/apps/myapp/streamer.go", line 107, in func2
  File "/go/src/github.com/blocknonip/myplatform/vendor/github.com/getsentry/raven-go/client.go", line 822, in CapturePanicAndWait
  File "/go/src/github.com/blocknonip/myplatform/vendor/github.com/getsentry/raven-go/client.go", line 828, in CapturePanicAndWait

[patrick-lachance]

This issue was happening in my project once a day. In 24 hours, millions of log entries were reported without issue. But when it happened it was always on
/go/pkg/mod/github.com/sirupsen/logrus@v1.4.2/entry.go:117

I worked around the problem by not using WithFields.
Instead I use:
logger.WithContext(context.WithValue(context.Background(), "fields", log.Fields{ ... }))

Then I use a hook to set field values into the entry.Data ...

[talbspx]

I am experiencing something similar on version 1.4.2.
by using a log entries hook which calls the WithField method to add a field to the entry before formatting it and sending it to log entries.

[epelc]

Is there any reason we can't just put a mutex on the Data map to protect it or add a method to do a copy of the map?

This issue also affects hooks which mutate data(ie add an extra field). #953

[dgsb]

duplicate of #1217

[dgsb]

should be fixed now