Send quit to timeout when RunWithTimeout command exits non-zero (#234)

When the command executed with RunWithTimeout failed and exited with
a non-zero exit code, we returned early and didn't send on the timeout's
quit channel. This defers the send on that channel right after we set up
the timeout goroutine so that we don't miss any code paths where it needs
to be sent.

commands/commands.go

@@ -194,6 +194,9 @@ func (c *Command) waitForTimeout() error {
 				return
 			}
 		}()
+		// if we send on this when we haven't set up the receiver
+		// we'll deadlock
+		defer func() { quit <- 0 }()
 	}
 	log.Debugf("%s.run waiting for PID %d: ", c.Name, cmd.Process.Pid)
 	state, err := cmd.Process.Wait()
@@ -209,12 +212,6 @@ func (c *Command) waitForTimeout() error {
 		return fmt.Errorf("%s exited with error", c.Name)
 	}
 
-	if doTimeout {
-		// if we send on this when we haven't set up the receiver
-		// we'll deadlock
-		log.Debugf("%s.run sent timeout quit", c.Name)
-		quit <- 0
-	}
 	log.Debugf("%s.run complete", c.Name)
 	return nil
 }

commands/commands_test.go

@@ -2,7 +2,10 @@ package commands
 
 import (
 	"errors"
+	"io/ioutil"
+	"os"
 	"runtime"
+	"strings"
 	"testing"
 	"time"
 
@@ -78,11 +81,29 @@ func TestRunWithTimeout(t *testing.T) {
 }
 
 func TestRunWithTimeoutFailed(t *testing.T) {
-	cmd, _ := NewCommand("./testdata/test.sh failStuff --debug", "0")
+
+	log.SetLevel(log.DebugLevel)
+	defer log.SetLevel(log.InfoLevel)
+
+	tmp, _ := ioutil.TempFile("", "tmp")
+	defer os.Remove(tmp.Name())
+
+	log.SetOutput(tmp)
+	defer log.SetOutput(os.Stdout)
+
+	cmd, _ := NewCommand("./testdata/test.sh failStuff --debug", "100ms")
 	fields := log.Fields{"process": "test"}
 	if err := RunWithTimeout(cmd, fields); err == nil {
 		t.Errorf("Expected error but got nil")
 	}
+	time.Sleep(200 * time.Millisecond)
+
+	buf, _ := ioutil.ReadFile(tmp.Name())
+	logs := string(buf)
+
+	if strings.Contains(logs, "timeout after") {
+		t.Fatalf("RunWithTimeout failed to cancel timeout after failure: %v", logs)
+	}
 }
 
 func TestEmptyCommand(t *testing.T) {