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
diff --git a/cmd/run_with_timeout/run_with_timeout.go b/cmd/run_with_timeout/run_with_timeout.go
index f2caaab..deaa842 100644
--- a/cmd/run_with_timeout/run_with_timeout.go
+++ b/cmd/run_with_timeout/run_with_timeout.go
@@ -47,7 +47,7 @@
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 @@
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 @@
if timeout > 0 {
timeoutCh = time.After(timeout)
}
+ startTime := time.Now()
select {
case err := <-waitCh:
@@ -126,10 +127,12 @@
// 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))
diff --git a/cmd/run_with_timeout/run_with_timeout_test.go b/cmd/run_with_timeout/run_with_timeout_test.go
index aebd336..ed6ec11 100644
--- a/cmd/run_with_timeout/run_with_timeout_test.go
+++ b/cmd/run_with_timeout/run_with_timeout_test.go
@@ -17,6 +17,7 @@
import (
"bytes"
"io"
+ "regexp"
"testing"
"time"
)
@@ -60,7 +61,8 @@
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 @@
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 @@
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)
}
})