search

docker / go-events

Composable event distribution for Go
Apache License 2.0
132 stars 23 forks source link

Don't include serialization of sink in log messages #18

Closed aaronlehmann closed 8 years ago

aaronlehmann commented 8 years ago

Some log messages add an events.sink field whose value is the actual sink object. Trying to log this can cause a data race, because some sinks contain a sync.Once field:

WARNING: DATA RACE
Read at 0x00c42004beb0 by goroutine 75:
  reflect.Value.Int()
      /usr/local/go/src/reflect/value.go:886 +0x192
  fmt.(*pp).printValue()
      /usr/local/go/src/fmt/print.go:703 +0x39f6
  fmt.(*pp).printValue()
      /usr/local/go/src/fmt/print.go:764 +0x2d45
  fmt.(*pp).printValue()
      /usr/local/go/src/fmt/print.go:764 +0x2d45
  fmt.(*pp).printValue()
      /usr/local/go/src/fmt/print.go:764 +0x2d45
  fmt.(*pp).printValue()
      /usr/local/go/src/fmt/print.go:835 +0x2448
  fmt.(*pp).printArg()
      /usr/local/go/src/fmt/print.go:668 +0x1a3
  fmt.(*pp).doPrint()
      /usr/local/go/src/fmt/print.go:1113 +0xe3
  fmt.Fprint()
      /usr/local/go/src/fmt/print.go:215 +0x69
  github.com/docker/swarmkit/vendor/github.com/Sirupsen/logrus.(*TextFormatter).appendKeyValue()
      /home/ubuntu/.go_workspace/src/github.com/docker/swarmkit/vendor/github.com/Sirupsen/logrus/text_formatter.go:157
+0x134
  github.com/docker/swarmkit/vendor/github.com/Sirupsen/logrus.(*TextFormatter).Format()
      /home/ubuntu/.go_workspace/src/github.com/docker/swarmkit/vendor/github.com/Sirupsen/logrus/text_formatter.go:91
+0x6e6
  github.com/docker/swarmkit/vendor/github.com/Sirupsen/logrus.(*Entry).Reader()
      /home/ubuntu/.go_workspace/src/github.com/docker/swarmkit/vendor/github.com/Sirupsen/logrus/entry.go:44
+0x73
  github.com/docker/swarmkit/vendor/github.com/Sirupsen/logrus.Entry.log()
      /home/ubuntu/.go_workspace/src/github.com/docker/swarmkit/vendor/github.com/Sirupsen/logrus/entry.go:94
+0x1f6
  github.com/docker/swarmkit/vendor/github.com/Sirupsen/logrus.(*Entry).Debug()
      /home/ubuntu/.go_workspace/src/github.com/docker/swarmkit/vendor/github.com/Sirupsen/logrus/entry.go:119
+0x106
  github.com/docker/swarmkit/vendor/github.com/docker/go-events.(*Queue).run()
      /home/ubuntu/.go_workspace/src/github.com/docker/swarmkit/vendor/github.com/docker/go-events/queue.go:85
+0x2eb

Previous write at 0x00c42004beb0 by goroutine 67:
  sync/atomic.AddInt32()
      /usr/local/go/src/runtime/race_amd64.s:269 +0xb
  sync.(*Mutex).Unlock()
      /usr/local/go/src/sync/mutex.go:109 +0x54
  sync.(*Once).Do()
      /usr/local/go/src/sync/once.go:46 +0xa6
  github.com/docker/swarmkit/vendor/github.com/docker/go-events.(*Channel).Close()
      /home/ubuntu/.go_workspace/src/github.com/docker/swarmkit/vendor/github.com/docker/go-events/channel.go:45
+0x79
  github.com/docker/swarmkit/manager/state/watch.(*Queue).CallbackWatch.func1()
      /home/ubuntu/.go_workspace/src/github.com/docker/swarmkit/manager/state/watch/watch.go:48
+0x9d
  github.com/docker/swarmkit/manager/state/watch.(*Queue).CallbackWatch.func2()
      /home/ubuntu/.go_workspace/src/github.com/docker/swarmkit/manager/state/watch/watch.go:62
+0x126
  github.com/docker/swarmkit/ca.(*Server).Run()
      /home/ubuntu/.go_workspace/src/github.com/docker/swarmkit/ca/server.go:380
+0xb25

To avoid the data race, add String methods to objects that aren't safe to serialize directly. These serialize a copy that excludes the sync.Once.

stevvooe commented 8 years ago

This is a classic error in logging for highly concurrent systems (seen this in Go and gevent). Rather than remove the portion of the logger, as that removes context, just evaluate the string at the callsite with fmt.Sprint. That way we keep the context and don't cause this error.

aaronlehmann commented 8 years ago

@stevvooe: I've changed this to continue logging the sink, and add String methods to the sinks that can't safely be dumped directly by reflection.

stevvooe commented 8 years ago

Though a little odd, LGTM