lib/exec/exec_test.go

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

package exec_test

import (
	"fmt"
	"io"
	"log"
	"os"
	"os/exec"
	"runtime"
	"strings"
	"sync"
	"syscall"
	"testing"
	"time"
	"unicode/utf8"

	"v.io/v23/verror"
	vexec "v.io/x/ref/lib/exec"
	// Use mock timekeeper to avoid actually sleeping during the test.
	"v.io/x/ref/test/timekeeper"
)

// We always expect there to be exactly three open file descriptors
// when the test starts out: STDIN, STDOUT, and STDERR. This
// assumption is tested in init below, and in the rare cases where it
// is wrong, we try to close all additional file descriptors, and bail
// out if that fails.
const baselineOpenFiles = 3

func init() {
	if os.Getenv("GOMAXPROCS") == "" {
		// Set the number of logical processors to 1 if GOMAXPROCS is
		// not set in the environment.
		//
		// TODO(caprita): the default in Go 1.5 is num cpus, which
		// causes flakiness.  Figure out why.
		runtime.GOMAXPROCS(1)
	}
	if os.Getenv("GO_WANT_HELPER_PROCESS_EXEC") == "1" {
		return
	}
	want, got := baselineOpenFiles, openFiles()
	if want == got {
		return
	}
	for i := want; i < got; i++ {
		syscall.Close(i)
	}
	if want, got = baselineOpenFiles, openFiles(); want != got {
		message := `Test expected to start with %d open files, found %d instead.
This can happen if parent process has any open file descriptors,
e.g. pipes, that are being inherited.`
		panic(fmt.Errorf(message, want, got))
	}
}

// These tests need to run a subprocess and we reuse this same test
// binary to do so. A fake test 'TestHelperProcess' contains the code
// we need to run in the child and we simply run this same binary with
// a test.run= arg that runs just that test. This idea was taken from
// the tests for os/exec.
func helperCommand(s ...string) *exec.Cmd {
	cs := []string{"-test.run=TestHelperProcess", "--"}
	cs = append(cs, s...)
	cmd := exec.Command(os.Args[0], cs...)
	cmd.Env = append([]string{"GO_WANT_HELPER_PROCESS_EXEC=1"}, os.Environ()...)
	return cmd
}

func openFiles() int {
	f, err := os.Open("/dev/null")
	if err != nil {
		panic("Failed to open /dev/null\n")
	}
	n := f.Fd()
	f.Close()
	return int(n)
}

func clean(t *testing.T, ph ...*vexec.ParentHandle) {
	for _, p := range ph {
		alreadyClean := !p.Exists()
		p.Clean()
		if !alreadyClean && p.Exists() {
			t.Errorf("child process left behind even after calling Clean")
		}
	}
	if want, got := baselineOpenFiles, openFiles(); want != got {
		t.Errorf("Leaking file descriptors: expect %d, got %d", want, got)
	}
}

func read(ch chan bool, r io.Reader, m string) {
	buf := make([]byte, 4096*4)
	n, err := r.Read(buf)
	if err != nil {
		log.Printf("failed to read message: error %s, expecting '%s'\n",
			err, m)
		ch <- false
		return
	}
	g := string(buf[:n])
	b := g == m
	if !b {
		log.Printf("read '%s', not '%s'\n", g, m)
	}
	ch <- b
}

func expectMessage(r io.Reader, m string) bool {
	ch := make(chan bool, 1)
	go read(ch, r, m)
	select {
	case b := <-ch:
		return b
	case <-time.After(5 * time.Second):
		log.Printf("expectMessage: timeout\n")
		return false
	}
}

func TestConfigExchange(t *testing.T) {
	cmd := helperCommand("testConfig")
	stderr, _ := cmd.StderrPipe()
	cfg := vexec.NewConfig()
	cfg.Set("foo", "bar")
	ph := vexec.NewParentHandle(cmd, vexec.ConfigOpt{Config: cfg})
	err := ph.Start()
	if err != nil {
		t.Fatalf("testConfig: start: %v", err)
	}
	serialized, err := cfg.Serialize()
	if err != nil {
		t.Fatalf("testConfig: failed to serialize config: %v", err)
	}
	if !expectMessage(stderr, serialized) {
		t.Errorf("unexpected output from child")
	} else {
		if err = cmd.Wait(); err != nil {
			t.Errorf("testConfig: wait: %v", err)
		}
	}
	clean(t, ph)
}

func TestSecretExchange(t *testing.T) {
	cmd := helperCommand("testSecret")
	stderr, _ := cmd.StderrPipe()
	ph := vexec.NewParentHandle(cmd, vexec.SecretOpt("dummy_secret"))
	err := ph.Start()
	if err != nil {
		t.Fatalf("testSecretTest: start: %v", err)
	}
	if !expectMessage(stderr, "dummy_secret") {
		t.Errorf("unexpected output from child")
	} else {
		if err = cmd.Wait(); err != nil {
			t.Errorf("testSecretTest: wait: %v", err)
		}
	}
	clean(t, ph)
}

func TestNoVersion(t *testing.T) {
	// Make sure that Init correctly tests for the presence of VEXEC_VERSION
	_, err := vexec.GetChildHandle()
	if verror.ErrorID(err) != vexec.ErrNoVersion.ID {
		t.Errorf("Should be missing Version")
	}
}

func waitForReady(t *testing.T, cmd *exec.Cmd, name string, delay int, ph *vexec.ParentHandle) error {
	err := ph.Start()
	if err != nil {
		t.Fatalf("%s: start: %v", name, err)
		return err
	}
	return ph.WaitForReady(time.Duration(delay) * time.Second)
}

func readyHelperCmd(t *testing.T, cmd *exec.Cmd, name, result string) *vexec.ParentHandle {
	stderr, err := cmd.StderrPipe()
	if err != nil {
		t.Fatalf("%s: failed to get stderr pipe\n", name)
	}
	ph := vexec.NewParentHandle(cmd)
	if err := waitForReady(t, cmd, name, 4, ph); err != nil {
		t.Errorf("%s: WaitForReady: %v (%v)", name, err, ph)
		return nil
	}
	if !expectMessage(stderr, result) {
		t.Errorf("%s: failed to read '%s' from child\n", name, result)
	}
	return ph
}

func readyHelper(t *testing.T, name, test, result string) *vexec.ParentHandle {
	cmd := helperCommand(test)
	return readyHelperCmd(t, cmd, name, result)
}

func testMany(t *testing.T, name, test, result string) []*vexec.ParentHandle {
	nprocs := 10
	ph := make([]*vexec.ParentHandle, nprocs)
	cmd := make([]*exec.Cmd, nprocs)
	stderr := make([]io.ReadCloser, nprocs)
	controlReaders := make([]io.ReadCloser, nprocs)
	var done sync.WaitGroup
	for i := 0; i < nprocs; i++ {
		cmd[i] = helperCommand(test)
		// The control pipe is used to signal the child when to wake up.
		controlRead, controlWrite, err := os.Pipe()
		if err != nil {
			t.Errorf("Failed to create control pipe: %v", err)
			return nil
		}
		controlReaders[i] = controlRead
		cmd[i].ExtraFiles = append(cmd[i].ExtraFiles, controlRead)
		stderr[i], _ = cmd[i].StderrPipe()
		tk := timekeeper.NewManualTime()
		ph[i] = vexec.NewParentHandle(cmd[i], vexec.TimeKeeperOpt{TimeKeeper: tk})
		done.Add(1)
		go func() {
			// For simulated slow children, wait until the parent
			// starts waiting, and then wake up the child.
			if test == "testReadySlow" {
				<-tk.Requests()
				tk.AdvanceTime(3 * time.Second)
				if _, err = controlWrite.Write([]byte("wake")); err != nil {
					t.Errorf("Failed to write to control pipe: %v", err)
				}
			}
			controlWrite.Close()
			done.Done()
		}()
		if err := ph[i].Start(); err != nil {
			t.Errorf("%s: Failed to start child %d: %s\n", name, i, err)
		}
	}
	for i := 0; i < nprocs; i++ {
		if err := ph[i].WaitForReady(5 * time.Second); err != nil {
			t.Errorf("%s: Failed to wait for child %d: %s\n", name, i, err)
		}
		controlReaders[i].Close()
	}
	for i := 0; i < nprocs; i++ {
		if !expectMessage(stderr[i], result) {
			t.Errorf("%s: Failed to read message from child %d\n", name, i)
		}
	}
	done.Wait()
	return ph
}

func TestToReadyMany(t *testing.T) {
	clean(t, testMany(t, "TestToReadyMany", "testReady", ".")...)
}

func TestToReadySlowMany(t *testing.T) {
	clean(t, testMany(t, "TestToReadySlowMany", "testReadySlow", "..")...)
}

func TestToReady(t *testing.T) {
	ph := readyHelper(t, "TestToReady", "testReady", ".")
	clean(t, ph)
}

func TestToFail(t *testing.T) {
	name := "testFail"
	cmd := helperCommand(name, "failed", "to", "start")
	ph := vexec.NewParentHandle(cmd)
	err := waitForReady(t, cmd, name, 4, ph)
	if err == nil || !strings.Contains(err.Error(), "failed to start") {
		t.Errorf("unexpected error: %v", err)
	}
}

func TestToFailInvalidUTF8(t *testing.T) {
	name := "testFail"
	cmd := helperCommand(name, "invalid", "utf8", string([]byte{0xFF}), "in", string([]byte{0xFC}), "error", "message")
	ph := vexec.NewParentHandle(cmd)
	err := waitForReady(t, cmd, name, 4, ph)
	if err == nil || !strings.Contains(err.Error(), "invalid utf8 "+string(utf8.RuneError)+" in "+string(utf8.RuneError)+" error message") {
		t.Errorf("unexpected error: %v", err)
	}
}

func TestNeverReady(t *testing.T) {
	name := "testNeverReady"
	result := "never ready"
	cmd := helperCommand(name)
	stderr, _ := cmd.StderrPipe()
	ph := vexec.NewParentHandle(cmd)
	err := waitForReady(t, cmd, name, 1, ph)
	if verror.ErrorID(err) != vexec.ErrTimeout.ID {
		t.Errorf("Failed to get timeout: got %v\n", err)
	} else {
		// block waiting for error from child
		if !expectMessage(stderr, result) {
			t.Errorf("%s: failed to read '%s' from child\n", name, result)
		}
	}
	clean(t, ph)
}

func TestTooSlowToReady(t *testing.T) {
	name := "testTooSlowToReady"
	result := "write status_wr: broken pipe"
	cmd := helperCommand(name)
	// The control pipe is used to signal the child when to wake up.
	controlRead, controlWrite, err := os.Pipe()
	if err != nil {
		t.Errorf("Failed to create control pipe: %v", err)
		return
	}
	cmd.ExtraFiles = append(cmd.ExtraFiles, controlRead)
	stderr, _ := cmd.StderrPipe()
	tk := timekeeper.NewManualTime()
	ph := vexec.NewParentHandle(cmd, vexec.TimeKeeperOpt{TimeKeeper: tk})
	defer clean(t, ph)
	defer controlWrite.Close()
	defer controlRead.Close()
	// Wait for the parent to start waiting, then simulate a timeout.
	go func() {
		toWait := <-tk.Requests()
		tk.AdvanceTime(toWait)
	}()
	err = waitForReady(t, cmd, name, 1, ph)
	if verror.ErrorID(err) != vexec.ErrTimeout.ID {
		t.Errorf("Failed to get timeout: got %v\n", err)
	} else {
		// After the parent timed out, wake up the child and let it
		// proceed.
		if _, err = controlWrite.Write([]byte("wake")); err != nil {
			t.Errorf("Failed to write to control pipe: %v", err)
		} else {
			// block waiting for error from child
			if !expectMessage(stderr, result) {
				t.Errorf("%s: failed to read '%s' from child\n", name, result)
			}
		}
	}
}

func TestToReadySlow(t *testing.T) {
	name := "TestToReadySlow"
	cmd := helperCommand("testReadySlow")
	// The control pipe is used to signal the child when to wake up.
	controlRead, controlWrite, err := os.Pipe()
	if err != nil {
		t.Errorf("Failed to create control pipe: %v", err)
		return
	}
	cmd.ExtraFiles = append(cmd.ExtraFiles, controlRead)
	stderr, err := cmd.StderrPipe()
	if err != nil {
		t.Fatalf("%s: failed to get stderr pipe", name)
	}
	tk := timekeeper.NewManualTime()
	ph := vexec.NewParentHandle(cmd, vexec.TimeKeeperOpt{TimeKeeper: tk})
	defer clean(t, ph)
	defer controlWrite.Close()
	defer controlRead.Close()
	// Wait for the parent to start waiting, simulate a short wait (but not
	// enough to timeout the parent), then wake up the child.
	go func() {
		<-tk.Requests()
		tk.AdvanceTime(2 * time.Second)
		if _, err = controlWrite.Write([]byte("wake")); err != nil {
			t.Errorf("Failed to write to control pipe: %v", err)
		}
	}()
	if err := waitForReady(t, cmd, name, 4, ph); err != nil {
		t.Errorf("%s: WaitForReady: %v (%v)", name, err, ph)
		return
	}
	// After the child has replied, simulate a timeout on the server by
	// advacing the time more; at this point, however, the timeout should no
	// longer occur since the child already replied.
	tk.AdvanceTime(2 * time.Second)
	if result := ".."; !expectMessage(stderr, result) {
		t.Errorf("%s: failed to read '%s' from child\n", name, result)
	}
}

func TestToCompletion(t *testing.T) {
	ph := readyHelper(t, "TestToCompletion", "testSuccess", "...ok")
	e := ph.Wait(10 * time.Second)
	if e != nil {
		t.Errorf("Wait failed: err %s\n", e)
	}
	clean(t, ph)
}

func TestToCompletionError(t *testing.T) {
	ph := readyHelper(t, "TestToCompletionError", "testError", "...err")
	e := ph.Wait(time.Second)
	if e == nil {
		t.Errorf("Wait failed: err %s\n", e)
	}
	clean(t, ph)
}

func TestExtraFiles(t *testing.T) {
	cmd := helperCommand("testExtraFiles")
	rd, wr, err := os.Pipe()
	if err != nil {
		t.Fatalf("Failed to create pipe: %s\n", err)
	}
	cmd.ExtraFiles = append(cmd.ExtraFiles, rd)
	msg := "hello there..."
	fmt.Fprintf(wr, msg)
	ph := readyHelperCmd(t, cmd, "TestExtraFiles", "child: "+msg)
	if ph == nil {
		t.Fatalf("Failed to get vexec.ParentHandle\n")
	}
	e := ph.Wait(10 * time.Second)
	if e != nil {
		t.Errorf("Wait failed: err %s\n", e)
	}
	rd.Close()
	wr.Close()
	clean(t, ph)
}

func TestExitEarly(t *testing.T) {
	name := "exitEarly"
	cmd := helperCommand(name)
	tk := timekeeper.NewManualTime()
	ph := vexec.NewParentHandle(cmd, vexec.TimeKeeperOpt{TimeKeeper: tk})
	err := ph.Start()
	if err != nil {
		t.Fatalf("%s: start: %v", name, err)
	}
	e := ph.Wait(time.Second)
	if e == nil || e.Error() != "exit status 1" {
		t.Errorf("Unexpected value for error: %v\n", e)
	}
	clean(t, ph)
}

func TestWaitAndCleanRace(t *testing.T) {
	name := "testReadyAndHang"
	cmd := helperCommand(name)
	tk := timekeeper.NewManualTime()
	ph := vexec.NewParentHandle(cmd, vexec.TimeKeeperOpt{TimeKeeper: tk})
	if err := waitForReady(t, cmd, name, 1, ph); err != nil {
		t.Errorf("%s: WaitForReady: %v (%v)", name, err, ph)
	}
	// Drain the tk.Requests() channel since waitForReady can leave something in it.
	select {
	case <-tk.Requests():
	default:
	}
	go func() {
		// Wait for the ph.Wait below to block, then advance the time
		// s.t. the Wait times out.
		<-tk.Requests()
		tk.AdvanceTime(2 * time.Second)
	}()
	if got, want := ph.Wait(time.Second), vexec.ErrTimeout.ID; got == nil || verror.ErrorID(got) != want {
		t.Errorf("Wait returned %v, wanted %v instead", got, want)
	}
	if got, want := ph.Clean(), "signal: killed"; got == nil || got.Error() != want {
		t.Errorf("Wait returned %v, wanted %v instead", got, want)
	}
}

func verifyNoExecVariable() {
	version := os.Getenv(vexec.ExecVersionVariable)
	if len(version) != 0 {
		log.Fatalf("Version variable %q has a value: %s", vexec.ExecVersionVariable, version)
	}
}

// TestHelperProcess isn't a real test; it's used as a helper process
// for the other tests.
func TestHelperProcess(*testing.T) {
	// Return immediately if this is not run as the child helper
	// for the other tests.
	if os.Getenv("GO_WANT_HELPER_PROCESS_EXEC") != "1" {
		return
	}
	defer os.Exit(0)

	version := os.Getenv(vexec.ExecVersionVariable)
	if len(version) == 0 {
		log.Fatalf("Version variable %q has no value", vexec.ExecVersionVariable)
	}

	// Write errors to stderr or using log. since the parent
	// process is reading stderr.
	args := os.Args
	for len(args) > 0 {
		if args[0] == "--" {
			args = args[1:]
			break
		}
		args = args[1:]
	}

	if len(args) == 0 {
		log.Fatal("No command")
	}

	cmd, args := args[0], args[1:]

	switch cmd {
	case "exitEarly":
		_, err := vexec.GetChildHandle()
		if err != nil {
			log.Fatal(err)
		}
		os.Exit(1)
	case "testNeverReady":
		_, err := vexec.GetChildHandle()
		if err != nil {
			log.Fatal(err)
		}
		verifyNoExecVariable()
		fmt.Fprintf(os.Stderr, "never ready")
	case "testTooSlowToReady":
		ch, err := vexec.GetChildHandle()
		if err != nil {
			log.Fatal(err)
		}
		verifyNoExecVariable()
		// Wait for the parent to tell us when it's ok to proceed.
		controlPipe := ch.NewExtraFile(0, "control_rd")
		for {
			buf := make([]byte, 100)
			n, err := controlPipe.Read(buf)
			if err != nil {
				log.Fatal(err)
			}
			if n > 0 {
				break
			}
		}
		// SetReady should return an error since the parent has
		// timed out on us and we'd be writing to a closed pipe.
		if err := ch.SetReady(); err != nil {
			fmt.Fprintf(os.Stderr, "%s", err)
		} else {
			fmt.Fprintf(os.Stderr, "didn't get the expected error")
		}
	case "testFail":
		ch, err := vexec.GetChildHandle()
		if err != nil {
			log.Fatal(err)
		}
		verifyNoExecVariable()
		err = ch.SetFailed(fmt.Errorf("%s", strings.Join(args, " ")))
		if err != nil {
			fmt.Fprintf(os.Stderr, "%s\n", err)
		}
		// It's fine to call SetFailed multiple times.
		if err2 := ch.SetFailed(fmt.Errorf("dummy")); err != err2 {
			fmt.Fprintf(os.Stderr, "Received new error got: %v, want %v\n", err2, err)
		}
	case "testReady":
		ch, err := vexec.GetChildHandle()
		if err != nil {
			log.Fatal(err)
		}
		verifyNoExecVariable()
		err = ch.SetReady()
		if err != nil {
			fmt.Fprintf(os.Stderr, "%s\n", err)
		}
		// It's fine to call SetReady multiple times.
		if err2 := ch.SetReady(); err != err2 {
			fmt.Fprintf(os.Stderr, "Received new error got: %v, want %v\n", err2, err)
		}
		fmt.Fprintf(os.Stderr, ".")
	case "testReadySlow":
		ch, err := vexec.GetChildHandle()
		if err != nil {
			log.Fatal(err)
		}
		verifyNoExecVariable()
		// Wait for the parent to tell us when it's ok to proceed.
		controlPipe := ch.NewExtraFile(0, "control_rd")
		for {
			buf := make([]byte, 100)
			n, err := controlPipe.Read(buf)
			if err != nil {
				log.Fatal(err)
			}
			if n > 0 {
				break
			}
		}
		ch.SetReady()
		fmt.Fprintf(os.Stderr, "..")
	case "testReadyAndHang":
		ch, err := vexec.GetChildHandle()
		if err != nil {
			log.Fatal(err)
		}
		verifyNoExecVariable()
		ch.SetReady()
		<-time.After(time.Minute)
	case "testSuccess", "testError":
		ch, err := vexec.GetChildHandle()
		if err != nil {
			log.Fatal(err)
		}
		verifyNoExecVariable()
		ch.SetReady()
		rc := make(chan int)
		go func() {
			if cmd == "testError" {
				fmt.Fprintf(os.Stderr, "...err")
				rc <- 1
			} else {
				fmt.Fprintf(os.Stderr, "...ok")
				rc <- 0
			}
		}()
		r := <-rc
		os.Exit(r)
	case "testConfig":
		ch, err := vexec.GetChildHandle()
		if err != nil {
			log.Fatalf("%v", err)
		} else {
			verifyNoExecVariable()
			serialized, err := ch.Config.Serialize()
			if err != nil {
				log.Fatalf("%v", err)
			}
			fmt.Fprintf(os.Stderr, "%s", serialized)
		}
	case "testSecret":
		ch, err := vexec.GetChildHandle()
		if err != nil {
			log.Fatalf("%s", err)
		} else {
			verifyNoExecVariable()
			fmt.Fprintf(os.Stderr, "%s", ch.Secret)
		}
	case "testExtraFiles":
		ch, err := vexec.GetChildHandle()
		if err != nil {
			log.Fatalf("error.... %s\n", err)
		}
		verifyNoExecVariable()
		err = ch.SetReady()
		rd := ch.NewExtraFile(0, "read")
		buf := make([]byte, 1024)
		if n, err := rd.Read(buf); err != nil {
			fmt.Fprintf(os.Stderr, "child: error %s\n", err)
		} else {
			fmt.Fprintf(os.Stderr, "child: %s", string(buf[:n]))
		}
	}
}