Add more debugging to run_with_timeout

Print more messages in run_with_timeout to make it easier to
determine which log statements came before the timeout and the
on_timeout command.

Test: run_with_timeout_test.go
Change-Id: I92ad663529fa03d91185ba382654a73f0eba1ab7

cmd/run_with_timeout/run_with_timeout.go

@@ -47,7 +47,7 @@ func main() {
 	flag.Parse()
 
 	if flag.NArg() < 1 {
-		fmt.Fprintln(os.Stderr, "command is required")
+		fmt.Fprintf(os.Stderr, "%s: error: command is required\n", os.Args[0])
 		usage()
 	}
 
@@ -55,9 +55,9 @@ func main() {
 		os.Stdin, os.Stdout, os.Stderr)
 	if err != nil {
 		if exitErr, ok := err.(*exec.ExitError); ok {
-			fmt.Fprintln(os.Stderr, "process exited with error:", exitErr.Error())
+			fmt.Fprintf(os.Stderr, "%s: process exited with error: %s\n", os.Args[0], exitErr.Error())
 		} else {
-			fmt.Fprintln(os.Stderr, "error:", err.Error())
+			fmt.Fprintf(os.Stderr, "%s: error: %s\n", os.Args[0], err.Error())
 		}
 		os.Exit(1)
 	}
@@ -115,6 +115,7 @@ func runWithTimeout(command string, args []string, timeout time.Duration, onTime
 	if timeout > 0 {
 		timeoutCh = time.After(timeout)
 	}
+	startTime := time.Now()
 
 	select {
 	case err := <-waitCh:
@@ -126,10 +127,12 @@ func runWithTimeout(command string, args []string, timeout time.Duration, onTime
 		// Continue below.
 	}
 
+	fmt.Fprintf(concurrentStderr, "%s: process timed out after %s\n", os.Args[0], time.Since(startTime))
 	// Process timed out before exiting.
 	defer cmd.Process.Signal(syscall.SIGKILL)
 
 	if onTimeoutCmdStr != "" {
+		fmt.Fprintf(concurrentStderr, "%s: running on_timeout command `%s`\n", os.Args[0], onTimeoutCmdStr)
 		onTimeoutCmd := exec.Command("sh", "-c", onTimeoutCmdStr)
 		onTimeoutCmd.Stdin, onTimeoutCmd.Stdout, onTimeoutCmd.Stderr = stdin, concurrentStdout, concurrentStderr
 		onTimeoutCmd.Env = append(os.Environ(), fmt.Sprintf("PID=%d", cmd.Process.Pid))

cmd/run_with_timeout/run_with_timeout_test.go

@@ -17,6 +17,7 @@ package main
 import (
 	"bytes"
 	"io"
+	"regexp"
 	"testing"
 	"time"
 )
@@ -60,7 +61,8 @@ func Test_runWithTimeout(t *testing.T) {
 				args:    []string{"-c", "sleep 1 && echo foo"},
 				timeout: 1 * time.Millisecond,
 			},
-			wantErr: true,
+			wantStderr: ".*: process timed out after .*\n",
+			wantErr:    true,
 		},
 		{
 			name: "on_timeout command",
@@ -71,6 +73,7 @@ func Test_runWithTimeout(t *testing.T) {
 				onTimeoutCmd: "echo bar",
 			},
 			wantStdout: "bar\n",
+			wantStderr: ".*: process timed out after .*\n.*: running on_timeout command `echo bar`\n",
 			wantErr:    true,
 		},
 	}
@@ -86,7 +89,7 @@ func Test_runWithTimeout(t *testing.T) {
 			if gotStdout := stdout.String(); gotStdout != tt.wantStdout {
 				t.Errorf("runWithTimeout() gotStdout = %v, want %v", gotStdout, tt.wantStdout)
 			}
-			if gotStderr := stderr.String(); gotStderr != tt.wantStderr {
+			if gotStderr := stderr.String(); !regexp.MustCompile(tt.wantStderr).MatchString(gotStderr) {
 				t.Errorf("runWithTimeout() gotStderr = %v, want %v", gotStderr, tt.wantStderr)
 			}
 		})