search

golang / mock

GoMock is a mocking framework for the Go programming language.
Apache License 2.0
9.3k stars 610 forks source link

Race condition between Call() and addAction #533

Closed aaronjwood closed 3 years ago

aaronjwood commented 3 years ago

I am hitting a race in gomock that's very similar to this https://github.com/golang/mock/issues/369

It looks like the main difference is that I'm racing Call() with addAction where the other issue is racing with Call and Return. Below is the test/code and the stack trace (had to mask out a few things):

func TestTokenRefresher_RefreshForever(t *testing.T) {
    k8sClient := fake.NewSimpleClientset(&v1.Secret{
        ObjectMeta: metav1.ObjectMeta{
            Name: "test",
        },
        Data: map[string][]byte{
            "token": []byte(refreshToken),
        },
    })

    refresher, err := jwt.NewTokenRefresher(k8sClient, "test", "")
    if err != nil {
        t.Fatal(err)
    }

    ctrl := gomock.NewController(t)
    defer ctrl.Finish()
    someServer := mockSome.NewMockMASKEDServer(ctrl)
    server := grpc.NewServer()
    some.RegisterMASKEDServer(server, someServer)
    lis, err := net.Listen("tcp", "localhost:0")
    if err != nil {
        t.Fatal(err)
    }

    go server.Serve(lis)
    err = refresher.Connect(lis.Addr().String(), libgrpc.Config{TLS: false})
    if err != nil {
        t.Fatal(err)
    }

    accessToken := "masked"
    someServer.EXPECT().RefreshToken(gomock.Any(), &empty.Empty{}).Return(&some.RefreshTokenResponse{
        Token: []byte(accessToken),
    }, nil)
    ctx, cancel := context.WithCancel(context.Background())
    ch := make(chan string)
    go refresher.RefreshForever(ctx, ch)
    if <-ch != accessToken {
        t.Fatal("Wrong token string")
    }

    wrongToken := "masked"
    someServer.EXPECT().RefreshToken(gomock.Any(), &empty.Empty{}).Return(&some.RefreshTokenResponse{
        Token: []byte(wrongToken),
    }, nil)
    if <-ch == accessToken {
        t.Fatal("Should have failed on wrong token string")
    }

    someServer.EXPECT().RefreshToken(gomock.Any(), &empty.Empty{}).Return(nil, errors.New(""))
    someServer.EXPECT().RefreshToken(gomock.Any(), &empty.Empty{}).Return(&someServer.RefreshTokenResponse{
        Token: []byte(accessToken),
    }, nil)
    if <-ch != accessToken {
        t.Fatal("Wrong token string")
    }

    cancel()
    _, ok := <-ch
    if ok {
        t.Fatal("Channel should have been closed from cancelling")
    }

    server.Stop()
}

The meat:

func (j *TokenRefresher) RefreshForever(ctx context.Context, ch chan<- string) {
    for {
        var claims *Claims
        var accessTokenStr string
        var err error

    inner:
        for {
            select {
            case <-ctx.Done():
                log.Infof("Stopping refreshing of access token")
                close(ch)
                return
            default:
                log.Infof("Refreshing access token")
                claims, accessTokenStr, err = j.RefreshAccessToken(ctx)
                if err != nil {
                    log.Errorf("Failed to refresh access token: %s", err.Error())
                    retryDuration := 5 * time.Second
                    log.Warnf("Retrying refreshing of the access token in %s", retryDuration)
                    time.Sleep(retryDuration)
                    continue inner
                }

                ch <- accessTokenStr
                break inner
            }
        }

        refreshDuration := time.Duration(claims.RefreshInterval) * time.Minute
        log.Infof("Access token successfully refreshed, refreshing again in %s", refreshDuration)
        time.Sleep(refreshDuration)
    }
}

The failures:

==================
 WARNING: DATA RACE
 Read at 0x00c0001a4fb8 by goroutine 57:
   github.com/golang/mock/gomock.(*Call).call()
       /root/go/pkg/mod/github.com/golang/mock@v1.4.3/gomock/call.go:408 +0x366
   github.com/golang/mock/gomock.(*Controller).Call.func1()
       /root/go/pkg/mod/github.com/golang/mock@v1.4.3/gomock/controller.go:212 +0x2fc
   github.com/golang/mock/gomock.(*Controller).Call()
       /root/go/pkg/mod/github.com/golang/mock@v1.4.3/gomock/controller.go:217 +0xdc
   MASKED.(*MockMASKEDServer).RefreshToken()
       /root/go/pkg/mod/MASKED/mock.go:125 +0x19d
   MASKED._MASKED_RefreshToken_Handler()
       /root/go/pkg/mod/MASKED/lifecycle.pb.go:538 +0x306
   google.golang.org/grpc.(*Server).processUnaryRPC()
       /root/go/pkg/mod/google.golang.org/grpc@v1.28.1/server.go:1082 +0xa05
   google.golang.org/grpc.(*Server).handleStream()
       /root/go/pkg/mod/google.golang.org/grpc@v1.28.1/server.go:1405 +0x138b
   google.golang.org/grpc.(*Server).serveStreams.func1.1()
       /root/go/pkg/mod/google.golang.org/grpc@v1.28.1/server.go:746 +0xdc
 Previous write at 0x00c0001a4fb8 by goroutine 40:
   github.com/golang/mock/gomock.(*Call).addAction()
       /root/go/pkg/mod/github.com/golang/mock@v1.4.3/gomock/call.go:426 +0x4a5
   github.com/golang/mock/gomock.(*Call).Return()
       /root/go/pkg/mod/github.com/golang/mock@v1.4.3/gomock/call.go:191 +0x36c
   MASKEDjwt_test.TestTokenRefresher_RefreshForever()
       MASKED/refresher_test.go:184 +0xf2b
   testing.tRunner()
       /usr/local/go/src/testing/testing.go:1123 +0x202
 Goroutine 57 (running) created at:
   google.golang.org/grpc.(*Server).serveStreams.func1()
       /root/go/pkg/mod/google.golang.org/grpc@v1.28.1/server.go:744 +0xb8
   google.golang.org/grpc/internal/transport.(*http2Server).operateHeaders()
       /root/go/pkg/mod/google.golang.org/grpc@v1.28.1/internal/transport/http2_server.go:447 +0x16e5
   google.golang.org/grpc/internal/transport.(*http2Server).HandleStreams()
       /root/go/pkg/mod/google.golang.org/grpc@v1.28.1/internal/transport/http2_server.go:488 +0x3e4
   google.golang.org/grpc.(*Server).serveStreams()
       /root/go/pkg/mod/google.golang.org/grpc@v1.28.1/server.go:742 +0x1c1
   google.golang.org/grpc.(*Server).handleRawConn.func1()
       /root/go/pkg/mod/google.golang.org/grpc@v1.28.1/server.go:703 +0x4c
 Goroutine 40 (running) created at:
   testing.(*T).Run()
       /usr/local/go/src/testing/testing.go:1168 +0x5bb
   testing.runTests.func1()
       /usr/local/go/src/testing/testing.go:1439 +0xa6
   testing.tRunner()
       /usr/local/go/src/testing/testing.go:1123 +0x202
   testing.runTests()
       /usr/local/go/src/testing/testing.go:1437 +0x612
   testing.(*M).Run()
       /usr/local/go/src/testing/testing.go:1345 +0x3b3
   main.main()
       _testmain.go:55 +0x236
 ==================
 ==================
 WARNING: DATA RACE
 Read at 0x00c0000e4b38 by goroutine 57:
   github.com/golang/mock/gomock.(*Controller).Call()
       /root/go/pkg/mod/github.com/golang/mock@v1.4.3/gomock/controller.go:220 +0x116
   MASKED.(*MockMASKEDServer).RefreshToken()
       /root/go/pkg/mod/MASKED/mock.go:125 +0x19d
   MASKED._MASKED_RefreshToken_Handler()
       /root/go/pkg/mod/MASKED/lifecycle.pb.go:538 +0x306
   google.golang.org/grpc.(*Server).processUnaryRPC()
       /root/go/pkg/mod/google.golang.org/grpc@v1.28.1/server.go:1082 +0xa05
   google.golang.org/grpc.(*Server).handleStream()
       /root/go/pkg/mod/google.golang.org/grpc@v1.28.1/server.go:1405 +0x138b
   google.golang.org/grpc.(*Server).serveStreams.func1.1()
       /root/go/pkg/mod/google.golang.org/grpc@v1.28.1/server.go:746 +0xdc
 Previous write at 0x00c0000e4b38 by goroutine 40:
   github.com/golang/mock/gomock.(*Call).addAction()
       /root/go/pkg/mod/github.com/golang/mock@v1.4.3/gomock/call.go:426 +0x46b
   github.com/golang/mock/gomock.(*Call).Return()
       /root/go/pkg/mod/github.com/golang/mock@v1.4.3/gomock/call.go:191 +0x36c
   MASKEDjwt_test.TestTokenRefresher_RefreshForever()
       MASKED/refresher_test.go:184 +0xf2b
   testing.tRunner()
       /usr/local/go/src/testing/testing.go:1123 +0x202
 Goroutine 57 (running) created at:
   google.golang.org/grpc.(*Server).serveStreams.func1()
       /root/go/pkg/mod/google.golang.org/grpc@v1.28.1/server.go:744 +0xb8
   google.golang.org/grpc/internal/transport.(*http2Server).operateHeaders()
       /root/go/pkg/mod/google.golang.org/grpc@v1.28.1/internal/transport/http2_server.go:447 +0x16e5
   google.golang.org/grpc/internal/transport.(*http2Server).HandleStreams()
       /root/go/pkg/mod/google.golang.org/grpc@v1.28.1/internal/transport/http2_server.go:488 +0x3e4
   google.golang.org/grpc.(*Server).serveStreams()
       /root/go/pkg/mod/google.golang.org/grpc@v1.28.1/server.go:742 +0x1c1
   google.golang.org/grpc.(*Server).handleRawConn.func1()
       /root/go/pkg/mod/google.golang.org/grpc@v1.28.1/server.go:703 +0x4c
 Goroutine 40 (running) created at:
   testing.(*T).Run()
       /usr/local/go/src/testing/testing.go:1168 +0x5bb
   testing.runTests.func1()
       /usr/local/go/src/testing/testing.go:1439 +0xa6
   testing.tRunner()
       /usr/local/go/src/testing/testing.go:1123 +0x202
   testing.runTests()
       /usr/local/go/src/testing/testing.go:1437 +0x612
   testing.(*M).Run()
       /usr/local/go/src/testing/testing.go:1345 +0x3b3
   main.main()
       _testmain.go:55 +0x236
 ==================

Go version: go version go1.15.8 darwin/amd64 Gomock version: gomock v1.4.3

codyoss commented 3 years ago

@aaronjwood Can you distill this down to a simpler test case? There are too many gaps for me to understand exactly what is going on here and where the problem might be.

marigs commented 3 years ago

I have the same problem. Easy way to reproduce it:

main.go:

package main

import "fmt"
import "time"

//go:generate go run -mod=mod github.com/golang/mock/mockgen -package main -destination=./mock_pub.go -source=main.go -build_flags=-mod=mod
type Publisher interface {
    Publish(i int) error
}

type StdoutPublisher struct {
}

func (StdoutPublisher) Publish(i int) error {
    fmt.Println(i)
    return nil
}

func PublishInts(p Publisher, n int) {
    for i := 0; i < n; i++ {
        go p.Publish(i)
    }
}

func main() {
    p := StdoutPublisher{}
    PublishInts(p, 2)
    time.Sleep(100 * time.Millisecond)
}

main_test.go:

package main

import (
    "testing"
    "time"

    "github.com/golang/mock/gomock"
)

func TestError1(t *testing.T) {
    ctrl := gomock.NewController(t)

    defer ctrl.Finish()

    m := NewMockPublisher(ctrl)

    N := 2

    for i := 0; i < N; i++ {
        go m.EXPECT().Publish(gomock.Any()).
            DoAndReturn(func(i int) error {
                println(i)
                return nil
            }).Times(1)
    }

    PublishInts(m, N)

    time.Sleep(100 * time.Millisecond)
}

my real code does not run m.EXPECT() in separated gorutines and I am not able to reproduce this bug with simple code when m.EXPECT() is run in the same gorutine. But in both cases top of stack traces are exactly the same:

WARNING: DATA RACE
Read at 0x00c000148348 by goroutine 10:
  github.com/golang/mock/gomock.(*Call).exhausted()
      /home/marigs/play/go/mock_error/vendor/github.com/golang/mock/gomock/call.go:422 +0x5cd
  github.com/golang/mock/gomock.(*Call).matches()
      /home/marigs/play/go/mock_error/vendor/github.com/golang/mock/gomock/call.go:527 +0x5e7
  github.com/golang/mock/gomock.callSet.FindMatch()
      /home/marigs/play/go/mock_error/vendor/github.com/golang/mock/gomock/callset.go:73 +0x24d
  github.com/golang/mock/gomock.(*Controller).Call.func1()
      /home/marigs/play/go/mock_error/vendor/github.com/golang/mock/gomock/controller.go:225 +0x1a9
  github.com/golang/mock/gomock.(*Controller).Call()
      /home/marigs/play/go/mock_error/vendor/github.com/golang/mock/gomock/controller.go:247 +0xdc
  mock_error.(*MockPublisher).Publish()
      /home/marigs/play/go/mock_error/mock_pub.go:39 +0x15d

Previous write at 0x00c000148348 by goroutine 8:
  github.com/golang/mock/gomock.(*Call).Times()
      /home/marigs/play/go/mock_error/vendor/github.com/golang/mock/gomock/call.go:340 +0xce
aaronjwood commented 3 years ago

Is it right to say that gomock isn't thread safe at all? I took a quick look at call.go and saw no protection anywhere. Even the counters are not using CAS logic. Are users of this lib expected to handle safety around the various calls themselves?

codyoss commented 3 years ago

There is mutex guarding with the controller. In general expects should be done in the main test goroutine but the mock can be passed around.

If I modify the example listed by marigs you can see this working:

func TestError1(t *testing.T) {
    ctrl := gomock.NewController(t)

    defer ctrl.Finish()

    m := NewMockPublisher(ctrl)

    N := 2

    for i := 0; i < N; i++ {
        n := i
        m.EXPECT().Publish(gomock.Any()).
            DoAndReturn(func(i int) error {
                println(n)
                return nil
            }).Times(2)
    }

    go PublishInts(m, N)
    go PublishInts(m, N)

    time.Sleep(100 * time.Millisecond)
}
codyoss commented 3 years ago

Closing this issue for now. I believe everything should work as expected with proper usage. It might be good to open up an issue and document how asynchronous code should be tested/mocked though.