Merge pull request #87 from taskcluster/bug1458873

Bug 1458873 - Fix task abortion

.taskcluster.yml

@@ -69,8 +69,8 @@ tasks:
       maxRunTime: 3600
       command:
         - set CGO_ENABLED=0
-        - set GOPATH=%CD%\gopath1.10.1
-        - set GOROOT=%CD%\go1.10.1\go
+        - set GOPATH=%CD%\gopath1.10.2
+        - set GOROOT=%CD%\go1.10.2\go
         - set PATH=%CD%\git\cmd;%GOPATH%\bin;%GOROOT%\bin;%PATH%
         - git config --global core.autocrlf false
         - go version
@@ -104,21 +104,21 @@ tasks:
         - set CGO_ENABLED=1
         - set GORACE=history_size=7
         - C:\generic-worker\generic-worker-test-creds.cmd
-        - 'go test -ldflags "-X github.com/taskcluster/generic-worker.revision=%revision%" -v -race ./...'
+        - 'go test -timeout 30m -ldflags "-X github.com/taskcluster/generic-worker.revision=%revision%" -v -race ./...'
         - set GW_TESTS_GENERATE_USERS=true
-        - 'go test -ldflags "-X github.com/taskcluster/generic-worker.revision=%revision%" -v -race'
+        - 'go test -timeout 30m -ldflags "-X github.com/taskcluster/generic-worker.revision=%revision%" -v -race'
         - ineffassign .
       artifacts:
         - name: public/build/generic-worker-windows-amd64.exe
-          path: gopath1.10.1\bin\generic-worker.exe
+          path: gopath1.10.2\bin\generic-worker.exe
           expires: "{{ '2 weeks' | $fromNow }}"
           type: file
       mounts:
         - cacheName: generic-worker-checkout
-          directory: gopath1.10.1\src
+          directory: gopath1.10.2\src
         - content:
-            url: https://storage.googleapis.com/golang/go1.10.1.windows-amd64.zip
-          directory: go1.10.1
+            url: https://storage.googleapis.com/golang/go1.10.2.windows-amd64.zip
+          directory: go1.10.2
           format: zip
         - content:
             url: https://github.com/git-for-windows/git/releases/download/v2.14.1.windows.1/MinGit-2.14.1-64-bit.zip
@@ -149,8 +149,8 @@ tasks:
       maxRunTime: 3600
       command:
         - set CGO_ENABLED=0
-        - set GOPATH=%CD%\gopath1.10.1
-        - set GOROOT=%CD%\go1.10.1\go
+        - set GOPATH=%CD%\gopath1.10.2
+        - set GOROOT=%CD%\go1.10.2\go
         - set PATH=%CD%\git\bin;%GOPATH%\bin;%GOROOT%\bin;%PATH%
         - git config --global core.autocrlf false
         - go version
@@ -174,21 +174,21 @@ tasks:
         - go get -ldflags "-X main.revision=%revision%" -v -u -t ./...
         - set GORACE=history_size=7
         - C:\generic-worker\generic-worker-test-creds.cmd
-        - 'go test -ldflags "-X github.com/taskcluster/generic-worker.revision=%revision%" -v ./...'
+        - 'go test -timeout 30m -ldflags "-X github.com/taskcluster/generic-worker.revision=%revision%" -v ./...'
         - set GW_TESTS_GENERATE_USERS=true
-        - 'go test -ldflags "-X github.com/taskcluster/generic-worker.revision=%revision%" -v'
+        - 'go test -timeout 30m -ldflags "-X github.com/taskcluster/generic-worker.revision=%revision%" -v'
         - ineffassign .
       artifacts:
         - name: public/build/generic-worker-windows-386.exe
-          path: gopath1.10.1\bin\generic-worker.exe
+          path: gopath1.10.2\bin\generic-worker.exe
           expires: "{{ '2 weeks' | $fromNow }}"
           type: file
       mounts:
         - cacheName: generic-worker-checkout
-          directory: gopath1.10.1\src
+          directory: gopath1.10.2\src
         - content:
-            url: https://storage.googleapis.com/golang/go1.10.1.windows-386.zip
-          directory: go1.10.1
+            url: https://storage.googleapis.com/golang/go1.10.2.windows-386.zip
+          directory: go1.10.2
           format: zip
         - content:
             url: https://github.com/git-for-windows/git/releases/download/v2.11.0.windows.3/Git-2.11.0.3-32-bit.tar.bz2
@@ -219,8 +219,8 @@ tasks:
       maxRunTime: 3600
       command:
         - set CGO_ENABLED=0
-        - set GOPATH=%CD%\gopath1.10.1
-        - set GOROOT=%CD%\go1.10.1\go
+        - set GOPATH=%CD%\gopath1.10.2
+        - set GOROOT=%CD%\go1.10.2\go
         - set PATH=%CD%\git\cmd;%GOPATH%\bin;%GOROOT%\bin;%PATH%
         - git config --global core.autocrlf false
         - go version
@@ -254,21 +254,21 @@ tasks:
         - set CGO_ENABLED=1
         - set GORACE=history_size=7
         - C:\generic-worker\generic-worker-test-creds.cmd
-        - 'go test -ldflags "-X github.com/taskcluster/generic-worker.revision=%revision%" -v -race ./...'
+        - 'go test -timeout 30m -ldflags "-X github.com/taskcluster/generic-worker.revision=%revision%" -v -race ./...'
         - set GW_TESTS_GENERATE_USERS=true
-        - 'go test -ldflags "-X github.com/taskcluster/generic-worker.revision=%revision%" -v -race'
+        - 'go test -timeout 30m -ldflags "-X github.com/taskcluster/generic-worker.revision=%revision%" -v -race'
         - ineffassign .
       artifacts:
         - name: public/build/generic-worker-windows-amd64.exe
-          path: gopath1.10.1\bin\generic-worker.exe
+          path: gopath1.10.2\bin\generic-worker.exe
           expires: "{{ '2 weeks' | $fromNow }}"
           type: file
       mounts:
         - cacheName: generic-worker-checkout
-          directory: gopath1.10.1\src
+          directory: gopath1.10.2\src
         - content:
-            url: https://storage.googleapis.com/golang/go1.10.1.windows-amd64.zip
-          directory: go1.10.1
+            url: https://storage.googleapis.com/golang/go1.10.2.windows-amd64.zip
+          directory: go1.10.2
           format: zip
         - content:
             url: https://github.com/git-for-windows/git/releases/download/v2.14.1.windows.1/MinGit-2.14.1-64-bit.zip
@@ -304,8 +304,8 @@ tasks:
           - -vxec
           - |
             export CGO_ENABLED=0
-            export GOROOT="$(pwd)/go1.10.1/go"
-            export GOPATH="$(pwd)/gopath1.10.1"
+            export GOROOT="$(pwd)/go1.10.2/go"
+            export GOPATH="$(pwd)/gopath1.10.2"
             export PATH="${GOPATH}/bin:${GOROOT}/bin:${PATH}"
             go version
             go env
@@ -327,19 +327,19 @@ tasks:
             go get -ldflags "-X main.revision=$(git rev-parse HEAD)" -v -u -t ./...
             # output of wc command can contain spaces on darwin, so no quotes around expression
             test $(git status --porcelain | wc -l) == 0
-            GORACE=history_size=7 CGO_ENABLED=1 go test -ldflags "-X github.com/taskcluster/generic-worker.revision=$(git rev-parse HEAD)" -race -v ./...
+            GORACE=history_size=7 CGO_ENABLED=1 go test -timeout 30m -ldflags "-X github.com/taskcluster/generic-worker.revision=$(git rev-parse HEAD)" -race -v ./...
             ineffassign .
       artifacts:
         - name: public/build/generic-worker-darwin-amd64
-          path: gopath1.10.1/bin/generic-worker
+          path: gopath1.10.2/bin/generic-worker
           expires: "{{ '2 weeks' | $fromNow }}"
           type: file
       mounts:
         - cacheName: generic-worker-checkout
-          directory: gopath1.10.1/src
+          directory: gopath1.10.2/src
         - content:
-            url: https://storage.googleapis.com/golang/go1.10.1.darwin-amd64.tar.gz
-          directory: go1.10.1
+            url: https://storage.googleapis.com/golang/go1.10.2.darwin-amd64.tar.gz
+          directory: go1.10.2
           format: tar.gz
 
 
@@ -375,8 +375,8 @@ tasks:
   #         - -vxec
   #         - |
   #           export CGO_ENABLED=0
-  #           export GOROOT="$(pwd)/go1.10.1/go"
-  #           export GOPATH="$(pwd)/gopath1.10.1"
+  #           export GOROOT="$(pwd)/go1.10.2/go"
+  #           export GOPATH="$(pwd)/gopath1.10.2"
   #           export PATH="${GOPATH}/bin:${GOROOT}/bin:${PATH}"
   #           export CGO_ENABLED=0
   #           go version
@@ -398,19 +398,19 @@ tasks:
   #           go generate
   #           go get -ldflags "-X main.revision=$(git rev-parse HEAD)" -v -u -t ./...
   #           test "$(git status --porcelain | wc -l)" == 0
-  #           GORACE=history_size=7 go test -ldflags "-X github.com/taskcluster/generic-worker.revision=$(git rev-parse HEAD)" -v ./...
+  #           GORACE=history_size=7 go test -timeout 30m -ldflags "-X github.com/taskcluster/generic-worker.revision=$(git rev-parse HEAD)" -v ./...
   #           ineffassign .
   #     artifacts:
   #       - name: public/build/generic-worker-linux-armv6l
-  #         path: gopath1.10.1/bin/generic-worker
+  #         path: gopath1.10.2/bin/generic-worker
   #         expires: "{{ '2 weeks' | $fromNow }}"
   #         type: file
   #     mounts:
   #       - cacheName: generic-worker-checkout
-  #         directory: gopath1.10.1/src
+  #         directory: gopath1.10.2/src
   #       - content:
-  #           url: https://storage.googleapis.com/golang/go1.10.1.linux-armv6l.tar.gz
-  #         directory: go1.10.1
+  #           url: https://storage.googleapis.com/golang/go1.10.2.linux-armv6l.tar.gz
+  #         directory: go1.10.2
   #         format: tar.gz
 
 
@@ -464,7 +464,7 @@ tasks:
           go generate
           go get -ldflags "-X main.revision=$(git rev-parse HEAD)" -v -u -t ./...
           test "$(git status --porcelain | wc -l)" == 0
-          GORACE=history_size=7 CGO_ENABLED=1 go test -ldflags "-X github.com/taskcluster/generic-worker.revision=$(git rev-parse HEAD)" -v -race ./...
+          GORACE=history_size=7 CGO_ENABLED=1 go test -timeout 30m -ldflags "-X github.com/taskcluster/generic-worker.revision=$(git rev-parse HEAD)" -v -race ./...
           "${GOPATH}/bin/ineffassign" .
       artifacts:
         public/build/generic-worker-linux-amd64:

.travis.yml

@@ -1,6 +1,6 @@
 language: go
 go:
-  - "1.10.1"
+  - "1.10.2"
 
 env:
   - "CGO_ENABLED=0 GIMME_OS=linux GIMME_ARCH=386"

chain_of_trust_windows.go

@@ -3,7 +3,6 @@ package main
 import (
 	"fmt"
 	"log"
-	"time"
 
 	"golang.org/x/sys/windows"
 
@@ -16,8 +15,7 @@ func (cot *ChainOfTrustTaskFeature) ensureTaskUserCantReadPrivateCotKey() error
 	if err != nil {
 		panic(fmt.Errorf("SERIOUS BUG: Could not get login info of task user to check it can't read chain of trust private key - %v", err))
 	}
-	TenSecondDeadline := time.Now().Add(time.Second * 10)
-	c, err := process.NewCommand([]string{"cmd.exe", "/c", "type", config.SigningKeyLocation}, cwd, nil, loginInfo, TenSecondDeadline)
+	c, err := process.NewCommand([]string{"cmd.exe", "/c", "type", config.SigningKeyLocation}, cwd, nil, loginInfo)
 	if err != nil {
 		panic(fmt.Errorf("SERIOUS BUG: Could not create command (not even trying to execute it yet) to cat private chain of trust key - %v", err))
 	}

helper_test.go

@@ -68,7 +68,7 @@ func setupEnvironment(t *testing.T, testName string) (teardown func()) {
 		// want to delete that, which is why we delete the TasksDir
 		err := os.RemoveAll(testDir)
 		if err != nil {
-			t.Fatalf("Not able to clean up after test: %v", err)
+			t.Logf("WARNING: Not able to clean up after test: %v", err)
 		}
 		taskContext = nil
 		globalTestName = ""

main.go

@@ -356,6 +356,7 @@ func initialiseFeatures() (err error) {
 			return err
 		}
 	}
+	log.Print("All features initialised.")
 	return nil
 }
 
@@ -1073,7 +1074,10 @@ func (task *TaskRun) setMaxRunTimer() *time.Timer {
 		func() {
 			// ignore any error the Abort function returns - we are in the
 			// wrong go routine to properly handle it
-			task.StatusManager.Abort(Failure(fmt.Errorf("Aborting task - max run time exceeded!")))
+			err := task.StatusManager.Abort(Failure(fmt.Errorf("Aborting task - max run time exceeded!")))
+			if err != nil {
+				task.Warnf("Error when aborting task: %v", err)
+			}
 		},
 	)
 }

main_test.go

@@ -26,12 +26,19 @@ func TestFailureResolvesAsFailure(t *testing.T) {
 func TestAbortAfterMaxRunTime(t *testing.T) {
 	defer setup(t, "TestAbortAfterMaxRunTime")()
 	payload := GenericWorkerPayload{
-		Command:    sleep(4),
-		MaxRunTime: 3,
+		Command: append(
+			sleep(27),
+			// also make sure subsequent commands after abort don't run
+			helloGoodbye()...,
+		),
+		MaxRunTime: 5,
 	}
 	td := testTask(t)
 
-	taskID := submitAndAssert(t, td, payload, "failed", "failed")
+	taskID := scheduleTask(t, td, payload)
+	startTime := time.Now()
+	ensureResolution(t, taskID, "failed", "failed")
+	endTime := time.Now()
 	// check uploaded log mentions abortion
 	// note: we do this rather than local log, to check also log got uploaded
 	// as failure path requires that task is resolved before logs are uploaded
@@ -50,11 +57,20 @@ func TestAbortAfterMaxRunTime(t *testing.T) {
 	}
 	logtext := string(bytes)
 	if !strings.Contains(logtext, "max run time exceeded") {
-		t.Fatalf("Was expecting log file to mention task abortion, but it doesn't")
+		t.Log("Was expecting log file to mention task abortion, but it doesn't:")
+		t.Fatal(logtext)
+	}
+	if strings.Contains(logtext, "hello") {
+		t.Log("Task should have been aborted before 'hello' was logged, but log contains 'hello':")
+		t.Fatal(logtext)
+	}
+	duration := endTime.Sub(startTime).Seconds()
+	if duration < 5 {
+		t.Fatalf("Task %v should have taken at least 5 seconds, but took %v seconds", taskID, duration)
+	}
+	if duration > 20 {
+		t.Fatalf("Task %v should have taken no more than 20 seconds, but took %v seconds", taskID, duration)
 	}
-	// TODO: this is a hack to make sure sleep process has died before we call teardown
-	// We need to make sure processes are properly killed when a task is aborted
-	time.Sleep(1500 * time.Millisecond)
 }
 
 func TestIdleWithoutCrash(t *testing.T) {

plat_windows.go

@@ -126,8 +126,7 @@ func prepareTaskUser(userName string) (reboot bool) {
 			panic(err)
 		}
 		if script := config.RunAfterUserCreation; script != "" {
-			var noDeadline time.Time
-			command, err := process.NewCommand([]string{script}, taskContext.TaskDir, nil, loginInfo, noDeadline)
+			command, err := process.NewCommand([]string{script}, taskContext.TaskDir, nil, loginInfo)
 			if err != nil {
 				panic(err)
 			}
@@ -218,7 +217,7 @@ func (task *TaskRun) generateCommand(index int) error {
 		task.Errorf("Cannot get handle of interactive user: %v", err)
 		return err
 	}
-	command, err := process.NewCommand([]string{wrapper}, taskContext.TaskDir, nil, loginInfo, task.maxRunTimeDeadline)
+	command, err := process.NewCommand([]string{wrapper}, taskContext.TaskDir, nil, loginInfo)
 	if err != nil {
 		return err
 	}

process/process_all-unix-style.go

@@ -5,6 +5,7 @@ package process
 import (
 	"fmt"
 	"io"
+	"log"
 	"os/exec"
 	"strconv"
 	"sync"
@@ -109,5 +110,11 @@ func (c *Command) DirectOutput(writer io.Writer) {
 func (c *Command) Kill() error {
 	c.mutex.Lock()
 	defer c.mutex.Unlock()
+	if c.Process == nil {
+		// If process hasn't been started yet, nothing to kill
+		return nil
+	}
+	log.Printf("Killing process with ID %v... (%p)", c.Process.Pid, c)
+	defer log.Printf("Process with ID %v killed.", c.Process.Pid)
 	return c.Process.Kill()
 }