fix(logger): Make MockLogger threadsafe (#441)

When using a `logger.MockLogger()`, a background goroutine calling
`logger.Noticef()` might race the underlying `bytes.Buffer` for
read/write access. To avoid that, limit the returned buffer type for
`MockLogger()` to just `fmt.Stringer` (and mutex-protect its reading
from the buffer) as well as mutex-protect `Write()` calls to the
underlying buffer.

To reproduce the race condition, run `go test -race ./internals/logger`
with `TestMockLoggerReadWriteThreadsafe` added, but with the unmodified
`MockLogger` implementation.

If more functions from `bytes.Buffer` are needed from the `MockLogger`
return value, the interface can be expanded with additional pass-through
lock-protected calls, but in all of Pebble, it seems only the
`.String()` function is used, so only that is exposed for now.

While `logger.Noticef()` calls are serialized by `logger.loggerLock`,
the same cannot be said for parallel access to the underlying
`bytes.Buffer` that is returned from `MockLogger` when calling
`logger.Noticef()` in one goroutine, and accessing the `bytes.Buffer`
from another goroutine.

internals/logger/logger.go

@@ -73,10 +73,27 @@ func Debugf(format string, v ...interface{}) {
 	logger.Debug(msg)
 }
 
+type lockedBytesBuffer struct {
+	buffer bytes.Buffer
+	mutex  sync.Mutex
+}
+
+func (b *lockedBytesBuffer) Write(p []byte) (int, error) {
+	b.mutex.Lock()
+	defer b.mutex.Unlock()
+	return b.buffer.Write(p)
+}
+
+func (b *lockedBytesBuffer) String() string {
+	b.mutex.Lock()
+	defer b.mutex.Unlock()
+	return b.buffer.String()
+}
+
 // MockLogger replaces the existing logger with a buffer and returns
-// the log buffer and a restore function.
-func MockLogger(prefix string) (buf *bytes.Buffer, restore func()) {
-	buf = &bytes.Buffer{}
+// a Stringer returning the log buffer content and a restore function.
+func MockLogger(prefix string) (fmt.Stringer, func()) {
+	buf := &lockedBytesBuffer{}
 	oldLogger := SetLogger(New(buf, prefix))
 	return buf, func() {
 		SetLogger(oldLogger)

internals/logger/logger_test.go

@@ -16,10 +16,12 @@ package logger_test
 
 import (
 	"bytes"
+	"fmt"
 	"os"
 	"testing"
 
 	. "gopkg.in/check.v1"
+	"gopkg.in/tomb.v2"
 
 	"github.com/canonical/pebble/internals/logger"
 )
@@ -30,7 +32,7 @@ func Test(t *testing.T) { TestingT(t) }
 var _ = Suite(&LogSuite{})
 
 type LogSuite struct {
-	logbuf        *bytes.Buffer
+	logbuf        fmt.Stringer
 	restoreLogger func()
 }
 
@@ -75,3 +77,19 @@ func (s *LogSuite) TestPanicf(c *C) {
 	c.Check(func() { logger.Panicf("xyzzy") }, Panics, "xyzzy")
 	c.Check(s.logbuf.String(), Matches, `20\d\d-\d\d-\d\dT\d\d:\d\d:\d\d.\d\d\dZ PREFIX: PANIC xyzzy\n`)
 }
+
+func (s *LogSuite) TestMockLoggerReadWriteThreadsafe(c *C) {
+	var t tomb.Tomb
+	t.Go(func() error {
+		for i := 0; i < 100; i++ {
+			logger.Noticef("foo")
+			logger.Noticef("bar")
+		}
+		return nil
+	})
+	for i := 0; i < 10; i++ {
+		logger.Noticef(s.logbuf.String())
+	}
+	err := t.Wait()
+	c.Check(err, IsNil)
+}