From 871574888b5baea46ada824d4a0907f7d9a4f0ae Mon Sep 17 00:00:00 2001 From: Jae Kwon Date: Thu, 31 May 2018 04:16:05 -0700 Subject: [PATCH] Make Execute and GoExecute log better --- cmd/gaia/cli_test/cli_test.go | 37 +++--------- tests/gobash.go | 104 ++++++++++++++++++++++---------- tests/process.go | 109 ++++++++++++++++++++++++++++++++++ 3 files changed, 190 insertions(+), 60 deletions(-) create mode 100644 tests/process.go diff --git a/cmd/gaia/cli_test/cli_test.go b/cmd/gaia/cli_test/cli_test.go index 0f549d6d6..7efe07f91 100644 --- a/cmd/gaia/cli_test/cli_test.go +++ b/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)) - defer cmd.Process.Kill() + proc := tests.GoExecuteT(t, fmt.Sprintf("gaiad start --rpc.laddr=%v", servAddr)) + 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)) - defer cmd.Process.Kill() + proc := tests.GoExecuteT(t, fmt.Sprintf("gaiad start --rpc.laddr=%v", servAddr)) + 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")) - if err != nil { - fmt.Println(err) - } + _, err := proc.StdinPipe.Write([]byte(write + "\n")) require.NoError(t, err) } - fmt.Printf("debug waiting cmdStr: %v\n", cmdStr) - 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)) + proc.Wait() } func executeInit(t *testing.T, cmdStr string) (chainID string) { diff --git a/tests/gobash.go b/tests/gobash.go index baa84f417..f46bad3c1 100644 --- a/tests/gobash.go +++ b/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 := strings.Split(command, " ") + // Split cmd to name and args. + split := strings.Split(cmd, " ") require.True(t, len(split) > 0, "no command provided") - - var cmd *exec.Cmd - if len(split) == 1 { - cmd = exec.Command(split[0]) - } else { - cmd = exec.Command(split[0], split[1:]...) + name, args := split[0], []string(nil) + if len(split) > 1 { + args = split[1:] } - return cmd -} -// Execute the command, return standard output and error, try a few times if requested -func ExecuteT(t *testing.T, command string) (out string) { - cmd := getCmd(t, command) - bz, err := cmd.CombinedOutput() - if err != nil { - panic(err) + // Start process and wait. + proc, err := StartProcess("", name, args, nil, nil) + require.NoError(t, err) + proc.Wait() + + // 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)) - out = strings.Trim(string(bz), "\n") //trim any new lines - time.Sleep(time.Second) + if len(errbz) > 0 { + t.Log("Stderr:", cmn.Red(string(errbz))) + } + + // Collect STDOUT output. + out = strings.Trim(string(outbz), "\n") //trim any new lines return out } -// Asynchronously execute the command, return standard output and error -func GoExecuteT(t *testing.T, command string) (cmd *exec.Cmd, pipeIn io.WriteCloser, pipeOut io.ReadCloser) { - cmd = getCmd(t, command) - pipeIn, err := cmd.StdinPipe() +// Execute the command, launch goroutines to log stdout/err to t. +// Caller should wait for .Wait() or .Stop() to terminate. +func GoExecuteT(t *testing.T, cmd string) (proc *Process) { + 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) - cmd.Start() - time.Sleep(time.Second) - return cmd, pipeIn, pipeOut + + // Run goroutines to log stdout. + go func() { + buf := make([]byte, 10240) // TODO Document the effects. + 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 } diff --git a/tests/process.go b/tests/process.go new file mode 100644 index 000000000..fcc6e3e0e --- /dev/null +++ b/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 +}