[THRIFT-4243] Go TSimpleServer race on wait in Stop() method

• Type: Bug
• Status: Closed
• Priority: Major
• Resolution: Fixed
• Fix Version/s: 0.11.0
• Component/s: Go - Library
• Assignee: Zach Wasserman
• Reporter: Zach Wasserman
• Created: 30/Jun/17 17:23
• Updated: 29/Mar/18 22:46
• Resolved: 01/Jul/17 14:03

Description

Synchronization issues with the use of sync.WaitGroup in the TSimpleServer implementation set off the race detector. Note the docs (https://godoc.org/sync#WaitGroup.Add) specify "calls with a positive delta that occur when the counter is zero must happen before a Wait".

The following unit test demonstrates the issue:

package thrift

import (
	"testing"
	"time"
)

type mockProcessor struct {
	ProcessFunc func(in, out TProtocol) (bool, TException)
}

func (m *mockProcessor) Process(in, out TProtocol) (bool, TException) {
	return m.ProcessFunc(in, out)
}

type mockServerTransport struct {
	ListenFunc    func() error
	AcceptFunc    func() (TTransport, error)
	CloseFunc     func() error
	InterruptFunc func() error
}

func (m *mockServerTransport) Listen() error {
	return m.ListenFunc()
}

func (m *mockServerTransport) Accept() (TTransport, error) {
	return m.AcceptFunc()
}

func (m *mockServerTransport) Close() error {
	return m.CloseFunc()
}

func (m *mockServerTransport) Interrupt() error {
	return m.InterruptFunc()
}

type mockTTransport struct {
	TTransport
}

func (m *mockTTransport) Close() error {
	return nil
}

func TestWaitRace(t *testing.T) {
	proc := &mockProcessor{
		ProcessFunc: func(in, out TProtocol) (bool, TException) {
			return false, nil
		},
	}

	trans := &mockServerTransport{
		ListenFunc: func() error {
			return nil
		},
		AcceptFunc: func() (TTransport, error) {
			return &mockTTransport{}, nil
		},
		CloseFunc: func() error {
			return nil
		},
		InterruptFunc: func() error {
			return nil
		},
	}

	serv := NewTSimpleServer2(proc, trans)
	go serv.Serve()
	time.Sleep(1)
	serv.Stop()
}

When run with the race detector, this test produces the following output:

go test -race -v -run TestWaitRace -count 1
=== RUN   TestWaitRace
==================
WARNING: DATA RACE
Write at 0x00c4200849f4 by goroutine 6:
  internal/race.Write()
      /usr/local/Cellar/go/1.8/libexec/src/internal/race/race.go:41 +0x38
  sync.(*WaitGroup).Wait()
      /usr/local/Cellar/go/1.8/libexec/src/sync/waitgroup.go:129 +0x14b
  git.apache.org/thrift.git/lib/go/thrift.(*TSimpleServer).Stop.func1()
      /Users/zwass/dev/go/src/git.apache.org/thrift.git/lib/go/thrift/simple_server.go:164 +0x9b
  sync.(*Once).Do()
      /usr/local/Cellar/go/1.8/libexec/src/sync/once.go:44 +0xe1
  git.apache.org/thrift.git/lib/go/thrift.(*TSimpleServer).Stop()
      /Users/zwass/dev/go/src/git.apache.org/thrift.git/lib/go/thrift/simple_server.go:166 +0x8c
  git.apache.org/thrift.git/lib/go/thrift.TestWaitRace()
      /Users/zwass/dev/go/src/git.apache.org/thrift.git/lib/go/thrift/simple_server_test.go:134 +0x1be
  testing.tRunner()
      /usr/local/Cellar/go/1.8/libexec/src/testing/testing.go:657 +0x107

Previous read at 0x00c4200849f4 by goroutine 7:
  internal/race.Read()
      /usr/local/Cellar/go/1.8/libexec/src/internal/race/race.go:37 +0x38
  sync.(*WaitGroup).Add()
      /usr/local/Cellar/go/1.8/libexec/src/sync/waitgroup.go:71 +0x26b
  git.apache.org/thrift.git/lib/go/thrift.(*TSimpleServer).AcceptLoop()
      /Users/zwass/dev/go/src/git.apache.org/thrift.git/lib/go/thrift/simple_server.go:139 +0xa6
  git.apache.org/thrift.git/lib/go/thrift.(*TSimpleServer).Serve()
      /Users/zwass/dev/go/src/git.apache.org/thrift.git/lib/go/thrift/simple_server.go:154 +0x86

Goroutine 6 (running) created at:
  testing.(*T).Run()
      /usr/local/Cellar/go/1.8/libexec/src/testing/testing.go:697 +0x543
  testing.runTests.func1()
      /usr/local/Cellar/go/1.8/libexec/src/testing/testing.go:882 +0xaa
  testing.tRunner()
      /usr/local/Cellar/go/1.8/libexec/src/testing/testing.go:657 +0x107
  testing.runTests()
      /usr/local/Cellar/go/1.8/libexec/src/testing/testing.go:888 +0x4e0
  testing.(*M).Run()
      /usr/local/Cellar/go/1.8/libexec/src/testing/testing.go:822 +0x1c3
  main.main()
      git.apache.org/thrift.git/lib/go/thrift/_test/_testmain.go:266 +0x20f

Goroutine 7 (running) created at:
  git.apache.org/thrift.git/lib/go/thrift.TestWaitRace()
      /Users/zwass/dev/go/src/git.apache.org/thrift.git/lib/go/thrift/simple_server_test.go:132 +0x1a3
  testing.tRunner()
      /usr/local/Cellar/go/1.8/libexec/src/testing/testing.go:657 +0x107
==================
--- FAIL: TestWaitRace (0.15s)
	testing.go:610: race detected during execution of test
panic: sync: WaitGroup is reused before previous Wait has returned [recovered]
	panic: sync: WaitGroup is reused before previous Wait has returned

goroutine 5 [running]:
testing.tRunner.func1(0xc42006aea0)
	/usr/local/Cellar/go/1.8/libexec/src/testing/testing.go:622 +0x55f
panic(0x14aea60, 0xc4201896a0)
	/usr/local/Cellar/go/1.8/libexec/src/runtime/panic.go:489 +0x2f0
sync.(*WaitGroup).Wait(0xc4200849e8)
	/usr/local/Cellar/go/1.8/libexec/src/sync/waitgroup.go:133 +0x138
git.apache.org/thrift.git/lib/go/thrift.(*TSimpleServer).Stop.func1()
	/Users/zwass/dev/go/src/git.apache.org/thrift.git/lib/go/thrift/simple_server.go:164 +0x9c
sync.(*Once).Do(0x174ce68, 0xc42002bf00)
	/usr/local/Cellar/go/1.8/libexec/src/sync/once.go:44 +0xe2
git.apache.org/thrift.git/lib/go/thrift.(*TSimpleServer).Stop(0xc420084980, 0x153af90, 0xc420084980)
	/Users/zwass/dev/go/src/git.apache.org/thrift.git/lib/go/thrift/simple_server.go:166 +0x8d
git.apache.org/thrift.git/lib/go/thrift.TestWaitRace(0xc42006aea0)
	/Users/zwass/dev/go/src/git.apache.org/thrift.git/lib/go/thrift/simple_server_test.go:134 +0x1bf
testing.tRunner(0xc42006aea0, 0x153b2b0)
	/usr/local/Cellar/go/1.8/libexec/src/testing/testing.go:657 +0x108
created by testing.(*T).Run
	/usr/local/Cellar/go/1.8/libexec/src/testing/testing.go:697 +0x544
exit status 2
FAIL	git.apache.org/thrift.git/lib/go/thrift	0.190s

Issue Links

• links to: GitHub Pull Request #1302
• links to: GitHub Pull Request #1523