Concurrent map error on text formatter caused by prefixFieldClashes

[kegsay]

Version: master/a283a10442df8dc09befd873fab202bf8a253d6a

Stack:

fatal error: concurrent map read and map write

goroutine 5168081 [running]:
runtime.throw(0xabc559, 0x21)
        /usr/local/go/src/runtime/panic.go:566 +0x95 fp=0xc43134f2d8 sp=0xc43134f2b8
runtime.mapaccess1_faststr(0xa0c9c0, 0xc43116c510, 0xaa4f7c, 0x4, 0x9b2020)
        /usr/local/go/src/runtime/hashmap_fast.go:201 +0x4f3 fp=0xc43134f338 sp=0xc43134f2d8
github.com/Sirupsen/logrus.(*TextFormatter).Format(0xc420014280, 0xc42226ff00, 0xc42226ff00, 0xc43134f530, 0x5112db, 0xc42016c660, 0xc42226ff00)
        /home/goneb/go-neb/vendor/src/github.com/Sirupsen/logrus/text_formatter.go:91 +0x47e fp=0xc43134f4c8 sp=0xc43134f338
github.com/Sirupsen/logrus.(*Entry).Reader(0xc42226ff00, 0xc42ecda704, 0xc42226ff00, 0x0)
        /home/goneb/go-neb/vendor/src/github.com/Sirupsen/logrus/entry.go:44 +0x40 fp=0xc43134f540 sp=0xc43134f4c8
github.com/Sirupsen/logrus.Entry.log(0xc4200181c0, 0xc43116c510, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x4, 0xc42915ef00, ...)
        /home/goneb/go-neb/vendor/src/github.com/Sirupsen/logrus/entry.go:94 +0x200 fp=0xc43134f600 sp=0xc43134f540
github.com/Sirupsen/logrus.(*Entry).Info(0xc42226fec0, 0xc43134f7a8, 0x1, 0x1)
        /home/goneb/go-neb/vendor/src/github.com/Sirupsen/logrus/entry.go:129 +0x9a fp=0xc43134f668 sp=0xc43134f600
github.com/Sirupsen/logrus.(*Entry).Print(0xc42226fec0, 0xc43134f7a8, 0x1, 0x1)
        /home/goneb/go-neb/vendor/src/github.com/Sirupsen/logrus/entry.go:124 +0x49 fp=0xc43134f698 sp=0xc43134f668

Something is writing to entry.Data - I've checked my own code and do not see any writes. However, prefixFieldClashes does modify the map if one of the fields is called level, msg or time (

logrus/formatter.go

Line 33 in 12ea3a4

func prefixFieldClashes(data Fields) {

), and indeed one of my fields is called msg.

I can work around this by renaming the field name on my end, but it would be nice if you could mention that you're modifying keys in the README.

[stevvooe]

@kegsay Any chance of running with the race detector?

For all intents and purposes, "time", "msg", and "level" should be considered reserved. If you want to add something to the README, please feel free to submit a PR.

[kegsay]

Ideally I would like it for logrus to warn about using those keys, though mentioning in the README that they should be considered reserved is probably also okay. In my particular case, I had innocently added the msg key without even thinking that logrus had the same key in use. Had logrus immediately logged a warning telling me not to use that key, I would've realised sooner.

I'll run it with the race detector and get back to you.

[stevvooe]

@kegsay So, it is mentioned in the README. I'm not really sure anything is actionable here. The behavior is documented and emitted messages are clearly not what was expected. Sometimes things are just learning experiences, rather than bugs. ;)

Would you like to submit a PR with a warning? That might be a little over-bearing, considering that some users of this package may not want the extra logs emitted for something they've been using for awhile.

[kegsay]

I see what you mean. I guess my main complaint isn't that the keys are in use and I'm silly for using the same key name. Instead, it's that it panics because I used the same key name. If it didn't, I wouldn't have noticed or cared, so I think you're right: the README doesn't need updating and I'm just being grumpy 😆

[kegsay]

Race detector with links to lines:

WARNING: DATA RACE
Read at 0x00c4201a01b0 by goroutine 7:
  github.com/Sirupsen/logrus.(*TextFormatter).Format()
      /....../go-neb/vendor/src/github.com/Sirupsen/logrus/text_formatter.go:60 +0x77
  github.com/matrix-org/dugong.(*fsHook).writeEntry()
      /....../go-neb/vendor/src/github.com/matrix-org/dugong/fshook.go:113 +0x7b
  github.com/matrix-org/dugong.NewFSHook.func1()
      /....../go-neb/vendor/src/github.com/matrix-org/dugong/fshook.go:86 +0x155

https://github.com/matrix-org/go-neb/blob/ae5b0df563569ddf6b639bfc3472db376a719fcc/vendor/src/github.com/Sirupsen/logrus/text_formatter.go#L60

Previous write at 0x00c4201a01b0 by goroutine 6:
  runtime.mapassign1()
      /usr/local/go/src/runtime/hashmap.go:442 +0x0
  github.com/Sirupsen/logrus.(*TextFormatter).Format()
      /....../go-neb/vendor/src/github.com/Sirupsen/logrus/text_formatter.go:71 +0xbb1
  github.com/Sirupsen/logrus.(*Entry).Reader()
      /....../go-neb/vendor/src/github.com/Sirupsen/logrus/entry.go:44 +0x73
  github.com/Sirupsen/logrus.Entry.log()
      /....../go-neb/vendor/src/github.com/Sirupsen/logrus/entry.go:94 +0x1f6
  github.com/Sirupsen/logrus.(*Entry).Info()
      /....../go-neb/vendor/src/github.com/Sirupsen/logrus/entry.go:129 +0x106
  github.com/Sirupsen/logrus.(*Entry).Print()
      /....../go-neb/vendor/src/github.com/Sirupsen/logrus/entry.go:124 +0x56
  github.com/matrix-org/go-neb/services/github.(*WebhookService).OnReceiveWebhook()
      /....../go-neb/src/github.com/matrix-org/go-neb/services/github/github_webhook.go:111 +0xc06
  github.com/matrix-org/go-neb/services/github.TestGithubWebhook()
      /....../go-neb/src/github.com/matrix-org/go-neb/services/github/github_webhook_test.go:229 +0xa51
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:610 +0xc9

https://github.com/matrix-org/go-neb/blob/ae5b0df563569ddf6b639bfc3472db376a719fcc/vendor/src/github.com/Sirupsen/logrus/text_formatter.go#L71

Goroutine 7 (running) created at:
  github.com/matrix-org/dugong.NewFSHook()
      /....../go-neb/vendor/src/github.com/matrix-org/dugong/fshook.go:91 +0x224
  github.com/matrix-org/go-neb/services/github.TestGithubWebhook()
      /....../go-neb/src/github.com/matrix-org/go-neb/services/github/github_webhook_test.go:38 +0x48d
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:610 +0xc9

https://github.com/matrix-org/go-neb/blob/ae5b0df563569ddf6b639bfc3472db376a719fcc/vendor/src/github.com/matrix-org/dugong/fshook.go#L91

Goroutine 6 (running) created at:
  testing.(*T).Run()
      /usr/local/go/src/testing/testing.go:646 +0x52f
  testing.RunTests.func1()
      /usr/local/go/src/testing/testing.go:793 +0xb9
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:610 +0xc9
  testing.RunTests()
      /usr/local/go/src/testing/testing.go:799 +0x4ba
  testing.(*M).Run()
      /usr/local/go/src/testing/testing.go:743 +0x12f
  main.main()
      /tmp/gb175901211/github.com/matrix-org/go-neb/services/github/_test/github.com/matrix-org/go-neb/services/_testmain.go:54 +0x1b8

---

So it looks like a hook reads from the entry in a goroutine which is racing with the write for the prefix field. I can confirm that renaming msg to message removes the data race.

[stevvooe]

@kegsay Grumpy is okay by me!

Thanks for the race tracebacks!

This isn't exactly ideal. Using msg, timestamp, and level should really be avoided but activating this race condition should not be the side-effect. I would prefer the package panic, but we can't really do that in a backwards compatible manner.

IMHO,

logrus/formatter.go

Line 33 in 12ea3a4

func prefixFieldClashes(data Fields) {

should really make a copy of data with the overridden fields. If you're feeling up to a PR, making prefixFieldClashes return a new copy would be reasonable (rsc's laments about immutability really come to bear here).

[kegsay]

Sure, I'll have a stab at this. It should be pretty easy to add a regression test for as well.

[dgsb]

@kegsay do you still reproduce this issue ? I suspect this should be fixed now as we are protecting the entry by a mutex