handle failed expectations in non-main goroutine

[jmhodges]

I use gomock to hide the details of third party services I don't control. The code that calls those services are often off the main goroutine.

Because of that, when tests fail due to expectation failures, gomock will emit a data race because it calls Fatalf (which calls FailNow) immediately off the main thread. That's, of course, not allowed by the testing package. https://golang.org/pkg/testing/#T.FailNow

I'm having to build out my own stubs in order to get around this problem. It'd be nice to not to!

This would probably require gomock panicing instead of relying on Fatalf to panic for it and delaying the Fatalf calls until ctrl.Finish is called.

[jmhodges]

(This is common, for instance, in tests of a web service that test the full database-to-html behavior.)

[jmhodges]

Ugh, that implementation idea doesn't work because on-main goroutine failures now will panic instead of just Fatalf'ing the test.

Maybe a handy wrapper TestReporter that delays the Fatalf calls for background goroutine use?

[jmhodges]

Well, the wrapping TestReporter doesn't work because the panics that the wrapping TestReporter needs to emit to behave like the current Fatalf call in Controller.Call will cause testing to exit the entire test process instead of just the test.

That one Fatalf in Controller.Call is the only place that needs to be delayed to make background goroutines work. It would be nice if we could have Controller.Call's reflection mechanisms to return bogus data (perhaps all zero values?) when we delay the firing of Fatalfs. Maybe that could be some optional behavior hidden by a different constructor function?

[jmhodges]

Ah, no, the zero values don't work either, of course. The code under test, of course, will panic on the nils returned and then you don't get to the deferred Finish method, anyway.

We could try to be smart about error types in the return values and panic otherwise. Hrm.

[balshetzer]

What if you wrote a TestReporter that called os.Exit(1) on Fatalf (after printing the error message)?

[jmhodges]

That would exit not just the one test that was running, but the entire test suite. Not desirable!

I went with:

// backgroundReporter is a wrapper for gomock's TestReporter that avoids data
// race issues with testing's FailNow methods. backgroundReporter assumes all
// calls to Fatalf and Errorf will happen off the main goroutine. Instead of
// using the inner TestReporter's Fatalf and Errorf to immediately update the
// test's state, it panics (to terminate the background goroutine it was called
// from) and only calls the inner Fatalf and Error methods during Finish. Finish
// should be called from the main goroutine in the test, similar to how
// gomock.Controller.Finish should be called. The tests may crash when the panic
// is called in the background goroutine, but this is not guaranteed, so the Finish
// call is desirable.
type backgroundReporter struct {
	t gomock.TestReporter

	mu     sync.Mutex
	fatalf []string
	errorf []string
}

func (br *backgroundReporter) Fatalf(msg string, args ...interface{}) {
	br.mu.Lock()
	defer br.mu.Unlock()
	s := fmt.Sprintf(msg, args...)
	br.fatalf = append(br.fatalf, s)
	panic(s)
}

func (br *backgroundReporter) Errorf(msg string, args ...interface{}) {
	br.mu.Lock()
	defer br.mu.Unlock()
	s := fmt.Sprintf(msg, args...)
	br.errorf = append(br.errorf, s)
	panic(s)
}

func (br *backgroundReporter) Finish() {
	br.mu.Lock()
	defer br.mu.Unlock()
	if len(br.errorf) != 0 {
		m := strings.Join(br.errorf, "\n  ")
		br.t.Errorf("delayed Errorf calls from a mock:\n  %s", m)
	}
	if len(br.fatalf) != 0 {
		m := strings.Join(br.fatalf, "\n  ")
		br.t.Fatalf("delayed Fatalf calls from a mock:\n  %s", m)
	}
}

[jmhodges]

It's still not a great solution. I think the output could be easier to understand if the TestReporter stuff got information about callsites the matches were made at (so we could sort the br.errorf and br.fatalf's) and maybe what objects were mismatched.

[balshetzer]

gomock does output all that info:

• the call sites of the actual calls
• the functions that didn't match and why

Are you using a recent version?

I'm looking into addressing the problem of what to do when there is a function call with no matching expectation outside of the test's goroutine.

[jmhodges]

Oh, it totally has it but in the string and I don’t think parsing that info back out of the messages in order to sort would work well, long-term.

[lavoiesl]

I experienced a similar issue where failed expectations inside a goroutine to not trigger the test to fail and just hang indefinitely:

Example:

package main_test

import (
	"reflect"
	"sync"
	"testing"

	"github.com/golang/mock/gomock"
	"github.com/stretchr/testify/assert"
)

type MockManager struct {
	ctrl     *gomock.Controller
	recorder *MockManagerMockRecorder
}

type MockManagerMockRecorder struct {
	mock *MockManager
}

func NewMockManager(ctrl *gomock.Controller) *MockManager {
	mock := &MockManager{ctrl: ctrl}
	mock.recorder = &MockManagerMockRecorder{mock}
	return mock
}

func (m *MockManager) EXPECT() *MockManagerMockRecorder {
	return m.recorder
}

func (m *MockManager) Func() {
	m.ctrl.T.Helper()
	m.ctrl.Call(m, "Func")
}

func (mr *MockManagerMockRecorder) Func() *gomock.Call {
	mr.mock.ctrl.T.Helper()
	return mr.mock.ctrl.RecordCallWithMethodType(mr.mock, "Func", reflect.TypeOf((*MockManager)(nil).Func))
}

func Test_goroutine_failed_expect(t *testing.T) {
	ctrl := gomock.NewController(t)
	defer ctrl.Finish()

	mgr := NewMockManager(ctrl)
	mgr.EXPECT().Func().Times(1)

	n := 5
	c := make(chan int, n)
	for i := 0; i < n; i++ {
		go func() {
			mgr.Func()
			c <- 1
		}()
	}

	for i := 0; i < n; i++ {
		assert.Equal(t, 1, <-c)
	}
}

Here's a different example:

func Test_goroutine_failed_expect(t *testing.T) {
	ctrl := gomock.NewController(t)
	defer ctrl.Finish()

	mgr := NewMockManager(ctrl)
	mgr.EXPECT().Func().Times(1)

	n := 5
	wg := &sync.WaitGroup{}
	for i := 0; i < n; i++ {
		wg.Add(1)
		go func() {
			mgr.Func()
			wg.Done()
		}()
	}

	wg.Wait()
}

Which results in:

=== RUN   Test_goroutine_failed_expect
fatal error: all goroutines are asleep - deadlock!

In both cases, changing the expectation to .Times(5) makes the test pass.

---

Removing the goroutines fails as expected:

	n := 5
	c := make(chan int, n)
	for i := 0; i < n; i++ {
		c <- mgr.Func()
	}

	for i := 0; i < n; i++ {
		assert.Equal(t, 1, <-c)
	}

--- FAIL: Test_goroutine_failed_expect (0.00s)
    foo_test.go:52: Unexpected call to *main_test.MockManager.Func([]) at test.go:32 because: 
        Expected call at test.go:47 has already been called the max number of times.

[codeinternist]

I've been running into the same issue as @lavoiesl - in this block of code:

if len(queue) == 1 {
    queue[0].Foo()
} else {
    var wg sync.WaitGroup
    var lock sync.Mutex
    for _, item := range queue {
        wg.Add(1)
        go func(item *itemType) {
            defer wg.Done()
            lock.Lock()
            item.Foo()
            lock.Unlock()
        }(item)
    }
    wg.Wait()
}        

if queue contains exactly 1 element, the predicted failed expect message appears:

--- FAIL: TestResolveQueue (0.00s)
    queue_test.go:422: Unexpected call to *mock_proto.ResolveQueue([]) at mock.go:65 because: 
        Expected call at expects.go:17 has already been called the max number of times.

If queue contains more than one element the tests hang, and at their conclusion the error message becomes:

panic: test timed out after 30s

followed by a stack dump of every running goroutine (without any reference to the EXPECT() failure).

[balshetzer]

The general solution to this problem is to build your own TestReporter.

When you create your controller it probably looks like this: NewController(t)
This works because testing.T implements the TestReporter interface. But, it implements it in a way that is not ideal for your use case. The solution is to build one that does what you want. Here is the TestReporter interface:

type TestReporter interface {
	Errorf(format string, args ...interface{})
	Fatalf(format string, args ...interface{})
}

The big question is what to do when Fatalf is called. I suppose you can call os.Exit(1) since just killing the current goroutine will most likely hang your test.