Make Execute and GoExecute log better

cmd/gaia/cli_test/cli_test.go

@@ -34,8 +34,8 @@ func TestGaiaCLISend(t *testing.T) {
 	flags := fmt.Sprintf("--node=%v --chain-id=%v", servAddr, chainID)
 
 	// start gaiad server
-	cmd, _, _ := tests.GoExecuteT(t, fmt.Sprintf("gaiad start --rpc.laddr=%v", servAddr))
+	proc := tests.GoExecuteT(t, fmt.Sprintf("gaiad start --rpc.laddr=%v", servAddr))
-	defer cmd.Process.Kill()
+	defer proc.Stop(false)
 
 	fooAddr, _ := executeGetAddrPK(t, "gaiacli keys show foo --output=json")
 	barAddr, _ := executeGetAddrPK(t, "gaiacli keys show bar --output=json")
@@ -83,8 +83,8 @@ func TestGaiaCLIDeclareCandidacy(t *testing.T) {
 	flags := fmt.Sprintf("--node=%v --chain-id=%v", servAddr, chainID)
 
 	// start gaiad server
-	cmd, _, _ := tests.GoExecuteT(t, fmt.Sprintf("gaiad start --rpc.laddr=%v", servAddr))
+	proc := tests.GoExecuteT(t, fmt.Sprintf("gaiad start --rpc.laddr=%v", servAddr))
-	defer cmd.Process.Kill()
+	defer proc.Stop(false)
 
 	fooAddr, _ := executeGetAddrPK(t, "gaiacli keys show foo --output=json")
 	barAddr, _ := executeGetAddrPK(t, "gaiacli keys show bar --output=json")
@@ -115,7 +115,7 @@ func TestGaiaCLIDeclareCandidacy(t *testing.T) {
 	declStr += fmt.Sprintf(" --validator-address=%v", bechVal)
 	declStr += fmt.Sprintf(" --amount=%v", "3steak")
 	declStr += fmt.Sprintf(" --moniker=%v", "bar-vally")
-	fmt.Printf("debug declStr: %v\n", declStr)
+	t.Log(fmt.Sprintf("debug declStr: %v\n", declStr))
 	executeWrite(t, declStr, pass)
 	time.Sleep(time.Second) // waiting for some blocks to pass
 	barAcc = executeGetAccount(t, fmt.Sprintf("gaiacli account %v %v", barAddr, flags))
@@ -132,7 +132,7 @@ func TestGaiaCLIDeclareCandidacy(t *testing.T) {
 	//unbondStr += fmt.Sprintf(" --address-delegator=%v", barAddr)
 	//unbondStr += fmt.Sprintf(" --shares=%v", "1")
 	//unbondStr += fmt.Sprintf(" --sequence=%v", "1")
-	//fmt.Printf("debug unbondStr: %v\n", unbondStr)
+	//t.Log(fmt.Sprintf("debug unbondStr: %v\n", unbondStr))
 	//executeWrite(t, unbondStr, pass)
 	//time.Sleep(time.Second * 3) // waiting for some blocks to pass
 	//barAcc = executeGetAccount(t, fmt.Sprintf("gaiacli account %v %v", barAddr, flags))
@@ -142,32 +142,13 @@ func TestGaiaCLIDeclareCandidacy(t *testing.T) {
 }
 
 func executeWrite(t *testing.T, cmdStr string, writes ...string) {
-	cmd, wc, _ := tests.GoExecuteT(t, cmdStr)
+	proc := tests.GoExecuteT(t, cmdStr)
 
 	for _, write := range writes {
-		_, err := wc.Write([]byte(write + "\n"))
+		_, err := proc.StdinPipe.Write([]byte(write + "\n"))
-		if err != nil {
-			fmt.Println(err)
-		}
 		require.NoError(t, err)
 	}
-	fmt.Printf("debug waiting cmdStr: %v\n", cmdStr)
+	proc.Wait()
-	cmd.Wait()
-}
-
-func executeWritePrint(t *testing.T, cmdStr string, writes ...string) {
-	cmd, wc, rc := tests.GoExecuteT(t, cmdStr)
-
-	for _, write := range writes {
-		_, err := wc.Write([]byte(write + "\n"))
-		require.NoError(t, err)
-	}
-	fmt.Printf("debug waiting cmdStr: %v\n", cmdStr)
-	cmd.Wait()
-
-	bz := make([]byte, 100000)
-	rc.Read(bz)
-	fmt.Printf("debug read: %v\n", string(bz))
 }
 
 func executeInit(t *testing.T, cmdStr string) (chainID string) {

tests/gobash.go

@@ -1,51 +1,91 @@
 package tests
 
 import (
-	"io"
-	"os/exec"
 	"strings"
 	"testing"
-	"time"
 
 	"github.com/stretchr/testify/require"
+	cmn "github.com/tendermint/tmlibs/common"
 )
 
-func getCmd(t *testing.T, command string) *exec.Cmd {
+// Execute the command, return stdout, logging stdout/err to t.
+func ExecuteT(t *testing.T, cmd string) (out string) {
+	t.Log("Running", cmn.Cyan(cmd))
 
-	//split command into command and args
+	// Split cmd to name and args.
-	split := strings.Split(command, " ")
+	split := strings.Split(cmd, " ")
 	require.True(t, len(split) > 0, "no command provided")
-
+	name, args := split[0], []string(nil)
-	var cmd *exec.Cmd
+	if len(split) > 1 {
-	if len(split) == 1 {
+		args = split[1:]
-		cmd = exec.Command(split[0])
-	} else {
-		cmd = exec.Command(split[0], split[1:]...)
 	}
-	return cmd
-}
 
-// Execute the command, return standard output and error, try a few times if requested
+	// Start process and wait.
-func ExecuteT(t *testing.T, command string) (out string) {
+	proc, err := StartProcess("", name, args, nil, nil)
-	cmd := getCmd(t, command)
+	require.NoError(t, err)
-	bz, err := cmd.CombinedOutput()
+	proc.Wait()
-	if err != nil {
+
-		panic(err)
+	// Get the output.
+	outbz := proc.StdoutBuffer.Bytes()
+	errbz := proc.StderrBuffer.Bytes()
+
+	// Log output.
+	if len(outbz) > 0 {
+		t.Log("Stdout:", cmn.Green(string(outbz)))
 	}
-	require.NoError(t, err, string(bz))
+	if len(errbz) > 0 {
-	out = strings.Trim(string(bz), "\n") //trim any new lines
+		t.Log("Stderr:", cmn.Red(string(errbz)))
-	time.Sleep(time.Second)
+	}
+
+	// Collect STDOUT output.
+	out = strings.Trim(string(outbz), "\n") //trim any new lines
 	return out
 }
 
-// Asynchronously execute the command, return standard output and error
+// Execute the command, launch goroutines to log stdout/err to t.
-func GoExecuteT(t *testing.T, command string) (cmd *exec.Cmd, pipeIn io.WriteCloser, pipeOut io.ReadCloser) {
+// Caller should wait for .Wait() or .Stop() to terminate.
-	cmd = getCmd(t, command)
+func GoExecuteT(t *testing.T, cmd string) (proc *Process) {
-	pipeIn, err := cmd.StdinPipe()
+	t.Log("Running", cmn.Cyan(cmd))
+
+	// Split cmd to name and args.
+	split := strings.Split(cmd, " ")
+	require.True(t, len(split) > 0, "no command provided")
+	name, args := split[0], []string(nil)
+	if len(split) > 1 {
+		args = split[1:]
+	}
+
+	// Start process.
+	proc, err := StartProcess("", name, args, nil, nil)
 	require.NoError(t, err)
-	pipeOut, err = cmd.StdoutPipe()
+
-	require.NoError(t, err)
+	// Run goroutines to log stdout.
-	cmd.Start()
+	go func() {
-	time.Sleep(time.Second)
+		buf := make([]byte, 10240) // TODO Document the effects.
-	return cmd, pipeIn, pipeOut
+		for {
+			n, err := proc.StdoutBuffer.Read(buf)
+			if err != nil {
+				return
+			}
+			if n > 0 {
+				t.Log("Stdout:", cmn.Green(string(buf[:n])))
+			}
+		}
+	}()
+
+	// Run goroutines to log stderr.
+	go func() {
+		buf := make([]byte, 10240) // TODO Document the effects.
+		for {
+			n, err := proc.StderrBuffer.Read(buf)
+			if err != nil {
+				return
+			}
+			if n > 0 {
+				t.Log("Stderr:", cmn.Red(string(buf[:n])))
+			}
+		}
+	}()
+
+	return proc
 }

tests/process.go

@@ -0,0 +1,109 @@
+package tests
+
+import (
+	"bytes"
+	"io"
+	"os"
+	"os/exec"
+	"time"
+)
+
+type Process struct {
+	ExecPath     string
+	Args         []string
+	Pid          int
+	StartTime    time.Time
+	EndTime      time.Time
+	Cmd          *exec.Cmd        `json:"-"`
+	ExitState    *os.ProcessState `json:"-"`
+	WaitCh       chan struct{}    `json:"-"`
+	StdinPipe    io.WriteCloser   `json:"-"`
+	StdoutBuffer *bytes.Buffer    `json:"-"`
+	StderrBuffer *bytes.Buffer    `json:"-"`
+}
+
+// dir: The working directory. If "", os.Getwd() is used.
+// name: Command name
+// args: Args to command. (should not include name)
+// outFile, errFile: If not nil, will use, otherwise new Buffers will be
+// allocated.  Either way, Process.Cmd.StdoutPipe and Process.Cmd.StderrPipe will be nil
+// respectively.
+func StartProcess(dir string, name string, args []string, outFile, errFile io.WriteCloser) (*Process, error) {
+	var cmd = exec.Command(name, args...) // is not yet started.
+	// cmd dir
+	if dir == "" {
+		pwd, err := os.Getwd()
+		if err != nil {
+			panic(err)
+		}
+		cmd.Dir = pwd
+	} else {
+		cmd.Dir = dir
+	}
+	// cmd stdin
+	stdin, err := cmd.StdinPipe()
+	if err != nil {
+		return nil, err
+	}
+	// cmd stdout, stderr
+	var outBuffer, errBuffer *bytes.Buffer
+	if outFile != nil {
+		cmd.Stdout = outFile
+	} else {
+		outBuffer = bytes.NewBuffer(nil)
+		cmd.Stdout = outBuffer
+	}
+	if errFile != nil {
+		cmd.Stderr = errFile
+	} else {
+		errBuffer = bytes.NewBuffer(nil)
+		cmd.Stderr = errBuffer
+	}
+	// cmd start
+	if err := cmd.Start(); err != nil {
+		return nil, err
+	}
+	proc := &Process{
+		ExecPath:  name,
+		Args:      args,
+		Pid:       cmd.Process.Pid,
+		StartTime: time.Now(),
+		Cmd:       cmd,
+		ExitState: nil,
+		WaitCh:    make(chan struct{}),
+		StdinPipe: stdin,
+	}
+	if outBuffer != nil {
+		proc.StdoutBuffer = outBuffer
+	}
+	if errBuffer != nil {
+		proc.StderrBuffer = errBuffer
+	}
+	go func() {
+		err := proc.Cmd.Wait()
+		if err != nil {
+			// fmt.Printf("Process exit: %v\n", err)
+			if exitError, ok := err.(*exec.ExitError); ok {
+				proc.ExitState = exitError.ProcessState
+			}
+		}
+		proc.ExitState = proc.Cmd.ProcessState
+		proc.EndTime = time.Now() // TODO make this goroutine-safe
+		close(proc.WaitCh)
+	}()
+	return proc, nil
+}
+
+func (proc *Process) Stop(kill bool) error {
+	if kill {
+		// fmt.Printf("Killing process %v\n", proc.Cmd.Process)
+		return proc.Cmd.Process.Kill()
+	} else {
+		// fmt.Printf("Stopping process %v\n", proc.Cmd.Process)
+		return proc.Cmd.Process.Signal(os.Interrupt)
+	}
+}
+
+func (proc *Process) Wait() {
+	<-proc.WaitCh
+}