Debugging interesting behavior with a common pattern for testing subprocesses and the race detector.

raceexec_test.go

package raceexec

import (
	"log"
	"os"
	"os/exec"
	"testing"
	"time"
)

// This one trick you won't believe to mock an external binary within test!
//
// Creates an exec.Cmd that actually calls back into the test binary itself,
// invoking a specific test function, with [-- cmd, args...] appended to end,
// and a magic env var specified.
//
// This allows us to easily mock external binary behavior in a cross-platform
// way. The go stdlib uses this trick in os/exec.Cmd's own tests!
//
// https://npf.io/2015/06/testing-exec-command/
func mockExecCommand(command string, args ...string) *exec.Cmd {
	cs := []string{"-test.run=TestHelperProcess", "--", command}
	cs = append(cs, args...)
	cmd := exec.Command(os.Args[0], cs...)
	cmd.Env = []string{"GO_WANT_HELPER_PROCESS=1"}
	return cmd
}

func TestHelperProcess(t *testing.T) {
	// ignore me when not being specifically invoked
	if os.Getenv("GO_WANT_HELPER_PROCESS") != "1" {
		return
	}
	// grab all the args after "--"
	var args []string
	for i, arg := range os.Args {
		if arg == "--" {
			args = os.Args[i+1:]
			break
		}
	}

	if len(args) == 0 {
		log.Fatal("mock command not specified")
	}
	switch args[0] {
	case "sleep": // variant of sleep, taking ParseDuration string
		t, _ := time.ParseDuration(args[1])
		time.Sleep(t)
		os.Exit(0)
	}
	log.Fatal("mocked command not implemented:", args[0])
}

func TestReportProcessDelay(t *testing.T) {
	for _, delay := range []string{"10ms", "100ms", "1s"} {
		c := mockExecCommand("sleep", delay)
		t.Log("running process which should sleep for:", delay)
		startTS := time.Now()
		err := c.Run()
		measuredRuntime := time.Since(startTS)
		if err != nil {
			t.Fatalf("failed to run cmd: %v", err)
		}
		t.Log("test measured time elapsed:", measuredRuntime)
	}
}

Update, this is related to: golang/go#20364
And can be resolved with the undocumented (in the go docs at least) env flag GORACE=atexit_sleep_ms=0