Merge lp:~dave-cheney/gocheck/003-serialise-log-writes into lp:gocheck

[Dave Cheney]

gocheck: serialize log writes

Fixes LP #1084878.

The race detector cannot profile gocheck tested code due to this race.

https://codereview.appspot.com/6862050/

[lp:~dave-cheney/gocheck/003-serialise-log-writes]

82. By Dave Cheney on 2012-12-06

wait for all workers to finish

[Roger Peppe (rogpeppe)]

LGTM with a few thoughts below

https://codereview.appspot.com/6862050/diff/5/gocheck.go
File gocheck.go (right):

https://codereview.appspot.com/6862050/diff/5/gocheck.go#newcode620
gocheck.go:620: type serialisedLogger struct {
s/serialisedLogger/logger/
and lose the interface type?

https://codereview.appspot.com/6862050/diff/5/helpers_test.go
File helpers_test.go (right):

https://codereview.appspot.com/6862050/diff/5/helpers_test.go#newcode441
helpers_test.go:441: go func(i int) {
personally i think that:
    i := i
reads more naturally than declaring a parameter and passing it.

https://codereview.appspot.com/6862050/diff/5/helpers_test.go#newcode449
helpers_test.go:449: start.Done()
this seems a slightly inappropriate use of sync.WaitGroup. i'd use a
channel for this and close it to start everything.

https://codereview.appspot.com/6862050/

[Gustavo Niemeyer (niemeyer)]

https://codereview.appspot.com/6862050/diff/5/gocheck.go
File gocheck.go (right):

https://codereview.appspot.com/6862050/diff/5/gocheck.go#newcode145
gocheck.go:145: func (c *C) writeLog(buf []byte) {
Isn't it enough to add a lock to this method?

https://codereview.appspot.com/6862050/

[Gustavo Niemeyer (niemeyer)]

https://codereview.appspot.com/6862050/diff/5/helpers_test.go
File helpers_test.go (right):

https://codereview.appspot.com/6862050/diff/5/helpers_test.go#newcode449
helpers_test.go:449: start.Done()
On 2012/12/06 06:51:57, rog wrote:
> this seems a slightly inappropriate use of sync.WaitGroup. i'd use a
channel for
> this and close it to start everything.

Why is it inappropriate? It feels very clean and clear to me.
Inappropriate != I haven't seen it before.

https://codereview.appspot.com/6862050/

[lp:~dave-cheney/gocheck/003-serialise-log-writes]

83. By Dave Cheney on 2012-12-07

responding to review feedback

[William Reade (fwereade)]

LGTM

https://codereview.appspot.com/6862050/

[lp:~dave-cheney/gocheck/003-serialise-log-writes]

84. By Dave Cheney on 2012-12-11

reverting to previous approach

[Roger Peppe (rogpeppe)]

On 2012/12/11 02:34:03, dfc wrote:
> Please take a look.

LGTM

https://codereview.appspot.com/6862050/

[Gustavo Niemeyer (niemeyer)]

LGTM

https://codereview.appspot.com/6862050/diff/27001/gocheck.go
File gocheck.go (right):

https://codereview.appspot.com/6862050/diff/27001/gocheck.go#newcode60
gocheck.go:60: writeLock sync.Mutex // protects logb from concurrent
writes
That's now unused.

https://codereview.appspot.com/6862050/diff/27001/gocheck.go#newcode74
gocheck.go:74: // logger concurrency safe byte.Buffer
logger is a

https://codereview.appspot.com/6862050/diff/27001/helpers_test.go
File helpers_test.go (right):

https://codereview.appspot.com/6862050/diff/27001/helpers_test.go#newcode450
helpers_test.go:450: stop.Wait()
Shouldn't be hard to have an assertion here checking that there wasn't
corruption.

https://codereview.appspot.com/6862050/

[Gustavo Niemeyer (niemeyer)]

*** Submitted:

gocheck: serialize log writes

Fixes LP #1084878.

The race detector cannot profile gocheck tested code due to this race.

R=rog, niemeyer, fwereade
CC=
https://codereview.appspot.com/6862050

https://codereview.appspot.com/6862050/

=== modified file 'gocheck.go'
--- gocheck.go	2012-07-22 21:58:00 +0000
+++ gocheck.go	2012-12-11 02:33:21 +0000
@@ -54,15 +54,16 @@
 }
 
 type C struct {
-	method   *methodType
-	kind     funcKind
-	status   funcStatus
-	logb     *bytes.Buffer
-	logw     io.Writer
-	done     chan *C
-	reason   string
-	mustFail bool
-	tempDir  *tempDir
+	method    *methodType
+	kind      funcKind
+	status    funcStatus
+	writeLock sync.Mutex // protects logb from concurrent writes
+	logb      *logger
+	logw      io.Writer
+	done      chan *C
+	reason    string
+	mustFail  bool
+	tempDir   *tempDir
 	timer
 }
 
@@ -70,6 +71,30 @@
 	runtime.Goexit()
 }
 
+// logger concurrency safe byte.Buffer
+type logger struct {
+	sync.Mutex
+	writer bytes.Buffer
+}
+
+func (l *logger) Write(buf []byte) (int, error) {
+	l.Lock()
+	defer l.Unlock()
+	return l.writer.Write(buf)
+}
+
+func (l *logger) WriteTo(w io.Writer) (int64, error) {
+	l.Lock()
+	defer l.Unlock()
+	return l.writer.WriteTo(w)
+}
+
+func (l *logger) String() string {
+	l.Lock()
+	defer l.Unlock()
+	return l.writer.String()
+}
+
 // -----------------------------------------------------------------------
 // Handling of temporary files and directories.
 
@@ -584,13 +609,13 @@
 
 // Create a call object with the given suite method, and fork a
 // goroutine with the provided dispatcher for running it.
-func (runner *suiteRunner) forkCall(method *methodType, kind funcKind, logb *bytes.Buffer, dispatcher func(c *C)) *C {
+func (runner *suiteRunner) forkCall(method *methodType, kind funcKind, logb *logger, dispatcher func(c *C)) *C {
 	var logw io.Writer
 	if runner.output.Stream {
 		logw = runner.output
 	}
 	if logb == nil {
-		logb = bytes.NewBuffer(nil)
+		logb = new(logger)
 	}
 	c := &C{
 		method:  method,
@@ -611,7 +636,7 @@
 }
 
 // Same as forkCall(), but wait for call to finish before returning.
-func (runner *suiteRunner) runFunc(method *methodType, kind funcKind, logb *bytes.Buffer, dispatcher func(c *C)) *C {
+func (runner *suiteRunner) runFunc(method *methodType, kind funcKind, logb *logger, dispatcher func(c *C)) *C {
 	c := runner.forkCall(method, kind, logb, dispatcher)
 	<-c.done
 	return c
@@ -654,7 +679,7 @@
 // goroutine like all suite methods, but this method will not return
 // while the fixture goroutine is not done, because the fixture must be
 // run in a desired order.
-func (runner *suiteRunner) runFixture(method *methodType, logb *bytes.Buffer) *C {
+func (runner *suiteRunner) runFixture(method *methodType, logb *logger) *C {
 	if method != nil {
 		c := runner.runFunc(method, fixtureKd, logb, func(c *C) {
 			c.ResetTimer()
@@ -670,7 +695,7 @@
 // Run the fixture method with runFixture(), but panic with a fixturePanic{}
 // in case the fixture method panics.  This makes it easier to track the
 // fixture panic together with other call panics within forkTest().
-func (runner *suiteRunner) runFixtureWithPanic(method *methodType, logb *bytes.Buffer, skipped *bool) *C {
+func (runner *suiteRunner) runFixtureWithPanic(method *methodType, logb *logger, skipped *bool) *C {
 	if *skipped {
 		return nil
 	}

=== modified file 'helpers_test.go'
--- helpers_test.go	2012-02-25 18:28:36 +0000
+++ helpers_test.go	2012-12-11 02:33:21 +0000
@@ -7,6 +7,8 @@
 	"launchpad.net/gocheck"
 	"os"
 	"reflect"
+	"runtime"
+	"sync"
 )
 
 var helpersS = gocheck.Suite(&HelpersS{})
@@ -126,7 +128,7 @@
 	testHelperFailure(c, "Check(1, checker, 2, msg)", false, false, log,
 		func() interface{} {
 			// Nice leading comment.
-			return c.Check(1, checker, 2)  // Hello there
+			return c.Check(1, checker, 2) // Hello there
 		})
 }
 
@@ -379,7 +381,6 @@
 		})
 }
 
-
 // -----------------------------------------------------------------------
 // MakeDir() tests.
 
@@ -429,6 +430,26 @@
 	return false
 }
 
+// Concurrent logging should not corrupt the underling buffer.
+// Use go test -race to detect the race in this test.
+func (s *HelpersS) TestConcurrentLogging(c *gocheck.C) {
+	defer runtime.GOMAXPROCS(runtime.GOMAXPROCS(runtime.NumCPU()))
+	var start, stop sync.WaitGroup
+	start.Add(1)
+	for i, n := 0, runtime.NumCPU()*2; i < n; i++ {
+		stop.Add(1)
+		go func(i int) {
+			start.Wait()
+			for j := 0; j < 30; j++ {
+				c.Logf("Worker %d: line %d", i, j)
+			}
+			stop.Done()
+		}(i)
+	}
+	start.Done()
+	stop.Wait()
+}
+
 // -----------------------------------------------------------------------
 // A couple of helper functions to test helper functions. :-)