src/runtime/semasleep_test.go

// Copyright 2018 The Go Authors. All rights reserved.
// Use of this source code is governed by a BSD-style
// license that can be found in the LICENSE file.

//go:build !plan9 && !windows && !js && !wasip1

package runtime_test

import (
	"io"
	"os/exec"
	"syscall"
	"testing"
	"time"
)

// Issue #27250. Spurious wakeups to pthread_cond_timedwait_relative_np
// shouldn't cause semasleep to retry with the same timeout which would
// cause indefinite spinning.
func TestSpuriousWakeupsNeverHangSemasleep(t *testing.T) {
	if *flagQuick {
		t.Skip("-quick")
	}
	t.Parallel() // Waits for a program to sleep for 1s.

	exe, err := buildTestProg(t, "testprog")
	if err != nil {
		t.Fatal(err)
	}

	cmd := exec.Command(exe, "After1")
	stdout, err := cmd.StdoutPipe()
	if err != nil {
		t.Fatalf("StdoutPipe: %v", err)
	}
	beforeStart := time.Now()
	if err := cmd.Start(); err != nil {
		t.Fatalf("Failed to start command: %v", err)
	}

	waiting := false
	doneCh := make(chan error, 1)
	t.Cleanup(func() {
		cmd.Process.Kill()
		if waiting {
			<-doneCh
		} else {
			cmd.Wait()
		}
	})

	// Wait for After1 to close its stdout so that we know the runtime's SIGIO
	// handler is registered.
	b, err := io.ReadAll(stdout)
	if len(b) > 0 {
		t.Logf("read from testprog stdout: %s", b)
	}
	if err != nil {
		t.Fatalf("error reading from testprog: %v", err)
	}

	// Wait for child exit.
	//
	// Note that we must do this after waiting for the write/child end of
	// stdout to close. Wait closes the read/parent end of stdout, so
	// starting this goroutine prior to io.ReadAll introduces a race
	// condition where ReadAll may get fs.ErrClosed if the child exits too
	// quickly.
	waiting = true
	go func() {
		doneCh <- cmd.Wait()
		close(doneCh)
	}()

	// The subprocess begins sleeping for 1s after it writes to stdout, so measure
	// the timeout from here (not from when we started creating the process).
	// That should reduce noise from process startup overhead.
	ready := time.Now()

	// With the repro running, we can continuously send to it
	// a signal that the runtime considers non-terminal,
	// such as SIGIO, to spuriously wake up
	// pthread_cond_timedwait_relative_np.
	ticker := time.NewTicker(200 * time.Millisecond)
	defer ticker.Stop()

	checkDoneErr := func(err error) {
		if err != nil {
			t.Fatalf("The program returned but unfortunately with an error: %v", err)
		}
		if time.Since(beforeStart) < 1*time.Second {
			// The program was supposed to sleep for a full (monotonic) second;
			// it should not return before that has elapsed.
			t.Fatalf("The program stopped too quickly.")
		}
	}
	signaled := 0
	for {
		select {
		// Wait for an arbitrary timeout longer than one second (we use the test binary's
		// timeout). The subprocess itself attempts to sleep for one second, but if the
		// machine running the test is heavily loaded that subprocess may not schedule
		// very quickly even if the bug remains fixed. (This is fine, because if the bug
		// really is unfixed we can keep the process hung indefinitely, as long as we
		// signal it often enough.)
		case <-t.Context().Done():
			// If we got paused for a long time for any reason (we're running in parallel
			// with other tests after all) it could be that the subprocess did actually
			// finish and not deadlock, we just got stuck as runnable or our wakeup was
			// delayed. Double-check that we don't have anything from doneCh before
			// declaring failure.
			select {
			case err := <-doneCh:
				checkDoneErr(err)
				return
			default:
			}

			// Send SIGQUIT to get a goroutine dump.
			// Stop sending SIGIO so that the program can clean up and actually terminate.
			cmd.Process.Signal(syscall.SIGQUIT)

			// For failure, we require that we have waited at least 2 seconds. Otherwise
			// if another test just ran for a long time and we just happened to push the
			// overall binary to timeout, we will report a failure here that will just
			// muddy the waters for whoever is trying to investigate the timeout.
			const minTime = 2 * time.Second
			if dur := time.Now().Sub(ready); dur > minTime {
				t.Logf("signaled program %d times", signaled)
				t.Logf("time waited: %v", dur)
				t.Error("program failed to return on time and has to be killed, issue #27520 still exists")
			} else {
				t.Skipf("test context deadline ended, but test ran for %s<%s, cutting it short", dur, minTime)
			}
			return
		case <-ticker.C:
			// Send the pesky signal that toggles spinning
			// indefinitely if #27520 is not fixed.
			cmd.Process.Signal(syscall.SIGIO)
			signaled++
		case err := <-doneCh:
			checkDoneErr(err)
			return
		}
	}
}