[ONPREM-2785] Add tests + decrease request timeout on task retries (#235)

* Add better acceptance test coverage around task-agent failure modes

* Add correlation to user-agent string

Make it easier to differentiate retried task instances

* Decrease overall runner API request timeout to 1m

5m was a bit excessive

* ./do license-attributions

* Attempt to fix tests on Windows

I think the tasks fail too quickly before the readiness probes have a chance

* Add changelog entry

Author: christian-stephen

CHANGELOG.md

@@ -10,6 +10,7 @@ By following these guidelines, we can easily determine which changes should be i
 
 ## Edge
 
+- [#235](https://github.com/circleci/runner-init/pull/235) Decrease runner API request timeout and add correlation string to requests.
 - [#174](https://github.com/circleci/runner-init/pull/174) Add support for a custom entrypoint override.
 - [#224](https://github.com/circleci/runner-init/pull/224) Record and log timings in orchestrator init function.
 - [#212](https://github.com/circleci/runner-init/pull/212) Fix child process cleanup on Windows using job objects. This ensures that child processes are destroyed when the parent process (task-agent) terminates.

acceptance/task_test.go

@@ -2,6 +2,7 @@ package acceptance
 
 import (
 	"fmt"
+	"net/http/httptest"
 	"os"
 	"path/filepath"
 	"runtime"
@@ -10,23 +11,26 @@ import (
 	"time"
 
 	"github.com/circleci/ex/testing/runner"
+	"github.com/circleci/ex/testing/testcontext"
 	"gotest.tools/v3/assert"
 	"gotest.tools/v3/assert/cmp"
+
+	"github.com/circleci/runner-init/internal/testing/fakerunnerapi"
 )
 
 func TestRunTask(t *testing.T) {
 	readinessFilePath := filepath.Join(t.TempDir(), "ready")
 	goodConfig := fmt.Sprintf(`
-{
-	"cmd": [],
-	"enable_unsafe_retries": false,
-	"token": "testtoken",
-	"readiness_file_path": "%v",
-	"task_agent_path": "%v",
-	"runner_api_base_url": "https://runner.circleci.com",
-	"allocation": "testallocation",
-	"max_run_time": 60000000000
-}`, strings.ReplaceAll(readinessFilePath, `\`, `\\`), strings.ReplaceAll(taskAgentBinary, `\`, `\\`))
+	{
+		"cmd": [],
+		"enable_unsafe_retries": false,
+		"token": "testtoken",
+		"readiness_file_path": "%v",
+		"task_agent_path": "%v",
+		"runner_api_base_url": "https://runner.circleci.com",
+		"allocation": "testallocation",
+		"max_run_time": 60000000000
+	}`, strings.ReplaceAll(readinessFilePath, `\`, `\\`), strings.ReplaceAll(taskAgentBinary, `\`, `\\`))
 
 	t.Run("Good run-task", func(t *testing.T) {
 		r := runner.New(
@@ -36,6 +40,7 @@ func TestRunTask(t *testing.T) {
 		)
 		res, err := r.Start(orchestratorTestBinaryRunTask)
 		assert.NilError(t, err)
+		defer func() { t.Log(res.Logs()) }()
 
 		t.Run("Probe for readiness", func(t *testing.T) {
 			assert.NilError(t, res.Ready("admin", time.Second*20))
@@ -67,8 +72,8 @@ func TestRunTask(t *testing.T) {
 
 		//nolint:gosec
 		err := os.WriteFile(entrypointPath, []byte(`#!/bin/bash
-echo "Executing custom entrypoint"
-exec "$@"`), 0750)
+	echo "Executing custom entrypoint"
+	exec "$@"`), 0750)
 		assert.NilError(t, err)
 
 		r := runner.New(
@@ -79,6 +84,7 @@ exec "$@"`), 0750)
 		)
 		res, err := r.Start(orchestratorTestBinaryOverride)
 		assert.NilError(t, err)
+		defer func() { t.Log(res.Logs()) }()
 
 		t.Run("Probe for readiness", func(t *testing.T) {
 			assert.NilError(t, res.Ready("admin", time.Second*20))
@@ -105,5 +111,108 @@ exec "$@"`), 0750)
 		})
 	})
 
-	// TODO: Add more test cases...
+	t.Run("task-agent exits with an error", func(t *testing.T) {
+		ctx := testcontext.Background()
+		runnerAPI := fakerunnerapi.New(ctx, []fakerunnerapi.Task{
+			{
+				Token:      "testtoken",
+				Allocation: "testallocation",
+			},
+		})
+		s := httptest.NewServer(runnerAPI)
+		t.Cleanup(s.Close)
+
+		badConfig := fmt.Sprintf(`
+	{
+		"cmd": [],
+		"enable_unsafe_retries": false,
+		"token": "testtoken",
+		"task_agent_path": "%v --bad-flag",
+		"runner_api_base_url": "%v",
+		"allocation": "testallocation",
+		"max_run_time": 60000000000
+	}`, strings.ReplaceAll(taskAgentBinary, `\`, `\\`), s.URL)
+
+		r := runner.New(
+			"CIRCLECI_GOAT_SHUTDOWN_DELAY=10s",
+			"CIRCLECI_GOAT_CONFIG="+badConfig,
+			"CIRCLECI_GOAT_HEALTH_CHECK_ADDR=:7624",
+		)
+		res, err := r.Start(orchestratorTestBinaryRunTask)
+		assert.NilError(t, err)
+		defer func() { t.Log(res.Logs()) }()
+
+		t.Run("Run task", func(t *testing.T) {
+			select {
+			case err = <-res.Wait():
+				assert.NilError(t, err, "handled errors should have a clean exit")
+			case <-time.After(time.Second * 40):
+				assert.NilError(t, res.Stop())
+				t.Fatal(t, "timeout before process stopped")
+			}
+		})
+
+		t.Run("Task failed", func(t *testing.T) {
+			assert.Check(t, cmp.Len(runnerAPI.TaskUnclaims(), 0))
+			assert.Check(t, cmp.DeepEqual(runnerAPI.TaskEvents(), []fakerunnerapi.TaskEvent{
+				{
+					Allocation:     "testallocation",
+					TimestampMilli: time.Now().UnixMilli(),
+					Message: []byte("error while executing task agent: " +
+						"task agent command exited with an unexpected error: " +
+						"exit status 80: circleci-agent: error: unknown flag --bad-flag\n: " +
+						"Check container logs for more details"),
+				},
+			}, fakerunnerapi.CmpTaskEvent))
+		})
+	})
+
+	t.Run("task-agent fails to start", func(t *testing.T) {
+		ctx := testcontext.Background()
+		runnerAPI := fakerunnerapi.New(ctx, []fakerunnerapi.Task{
+			{
+				ID:         "testid",
+				Token:      "testtoken",
+				Allocation: "testallocation",
+			},
+		})
+		s := httptest.NewServer(runnerAPI)
+		t.Cleanup(s.Close)
+
+		badConfig := fmt.Sprintf(`
+	{
+		"cmd": [],
+		"enable_unsafe_retries": false,
+		"task_id": "testid",
+		"token": "testtoken",
+		"task_agent_path": "thiswillfailtostart",
+		"runner_api_base_url": "%v",
+		"allocation": "testallocation",
+		"max_run_time": 60000000000
+	}`, s.URL)
+
+		r := runner.New(
+			"CIRCLECI_GOAT_SHUTDOWN_DELAY=10s",
+			"CIRCLECI_GOAT_CONFIG="+badConfig,
+			"CIRCLECI_GOAT_HEALTH_CHECK_ADDR=:7624",
+		)
+		res, err := r.Start(orchestratorTestBinaryRunTask)
+		assert.NilError(t, err)
+		defer func() { t.Log(res.Logs()) }()
+
+		t.Run("Run task", func(t *testing.T) {
+			select {
+			case err = <-res.Wait():
+				assert.NilError(t, err, "handled errors should have a clean exit")
+			case <-time.After(time.Second * 40):
+				assert.NilError(t, res.Stop())
+				t.Fatal(t, "timeout before process stopped")
+			}
+		})
+
+		t.Run("Task unclaimed - this is a safe error to retry", func(t *testing.T) {
+			assert.Check(t, cmp.Len(runnerAPI.TaskUnclaims(), 1))
+			assert.Check(t, cmp.Len(runnerAPI.TaskEvents(), 0))
+		})
+	})
 }

clients/runner/client.go

@@ -10,6 +10,7 @@ import (
 
 	"github.com/circleci/ex/config/secret"
 	"github.com/circleci/ex/httpclient"
+	"github.com/circleci/ex/httpclient/dnscache"
 	"github.com/circleci/ex/httpclient/metrics"
 	"github.com/circleci/ex/o11y"
 )
@@ -29,10 +30,13 @@ type ClientConfig struct {
 
 type Info struct {
 	AgentVersion string
+	// Correlation should be a unique-ish string to correlate API requests and logs
+	Correlation string
 }
 
 func (i Info) userAgent() string {
-	return fmt.Sprintf("CircleCI-GOAT/%s (%s; %s)", i.AgentVersion, runtime.GOOS, runtime.GOARCH)
+	return fmt.Sprintf("CircleCI-GOAT/%s (%s; %s; %s)",
+		i.AgentVersion, runtime.GOOS, runtime.GOARCH, i.Correlation)
 }
 
 func NewClient(c ClientConfig) *Client {
@@ -41,8 +45,11 @@ func NewClient(c ClientConfig) *Client {
 		BaseURL:    c.BaseURL,
 		AuthToken:  string(c.AuthToken),
 		AcceptType: httpclient.JSON,
-		Timeout:    time.Minute * 5,
+		Timeout:    time.Minute * 1,
 		UserAgent:  c.Info.userAgent(),
+		DialContext: dnscache.DialContext(dnscache.New(dnscache.Config{
+			TTL: 30 * time.Second,
+		}), nil),
 	}
 
 	if c.Tracer != nil {

cmd/orchestrator/main.go

@@ -6,13 +6,15 @@ import (
 	"fmt"
 	"log" //nolint:depguard // a non-O11y log is allowed for a top-level fatal exit
 	"os"
+	"strings"
 	"time"
 
 	"github.com/alecthomas/kong"
 	"github.com/circleci/ex/httpserver/healthcheck"
 	"github.com/circleci/ex/o11y"
 	"github.com/circleci/ex/system"
 	"github.com/circleci/ex/termination"
+	"github.com/circleci/ex/testing/testrand"
 
 	"github.com/circleci/runner-init/clients/runner"
 	"github.com/circleci/runner-init/cmd"
@@ -131,6 +133,7 @@ func runSetup(ctx context.Context, cli cli, version string, sys *system.System)
 		AuthToken: c.Config.Token,
 		Info: runner.Info{
 			AgentVersion: version,
+			Correlation:  correlation(),
 		},
 	})
 
@@ -145,6 +148,18 @@ func runSetup(ctx context.Context, cli cli, version string, sys *system.System)
 	return o, nil
 }
 
+// correlation returns a unique-ish string to correlate API requests and logs.
+// We prefer the Pod name, which we currently get via the hostname since we don't inject it into the task
+// environment yet. However, hostname is not fully reliable (it can be overridden in the Pod spec, or some
+// providers may not set it to the Pod name), so we fall back to a pseudo-random hex string if needed.
+func correlation() string {
+	hostname, _ := os.Hostname()
+	if strings.HasPrefix(hostname, "ccita-") {
+		return hostname
+	}
+	return testrand.Hex(8)
+}
+
 type Runner interface {
 	Run(ctx context.Context) error
 }

go-project-licenses.csv

@@ -2,6 +2,7 @@ Name,License
 github.com/DataDog/datadog-go/statsd,MIT
 github.com/alecthomas/kong,MIT
 github.com/cenkalti/backoff/v5,MIT
+github.com/cespare/xxhash/v2,MIT
 github.com/circleci/ex,MIT
 github.com/circleci/runner-init,Apache-2.0
 github.com/facebookgo/clock,MIT
@@ -38,6 +39,7 @@ github.com/quic-go/qpack,MIT
 github.com/quic-go/quic-go,MIT
 github.com/rollbar/rollbar-go,MIT
 github.com/ugorji/go/codec,MIT
+github.com/vmihailenco/go-tinylfu,MIT
 github.com/vmihailenco/msgpack/v5,BSD-2-Clause
 github.com/vmihailenco/tagparser/v2,BSD-2-Clause
 go.opentelemetry.io/auto/sdk,Apache-2.0

go.mod

@@ -522,6 +522,7 @@ require (
 	github.com/uudashr/iface v1.4.1 // indirect
 	github.com/vbatts/tar-split v0.12.1 // indirect
 	github.com/vektah/gqlparser/v2 v2.5.27 // indirect
+	github.com/vmihailenco/go-tinylfu v0.2.2 // indirect
 	github.com/wagoodman/go-partybus v0.0.0-20230516145632-8ccac152c651 // indirect
 	github.com/wagoodman/go-progress v0.0.0-20220614130704-4b1c25a33c7c // indirect
 	github.com/whyrusleeping/cbor-gen v0.1.3-0.20240731173018-74d74643234c // indirect

go.sum

@@ -379,6 +379,7 @@ github.com/cenkalti/backoff/v5 v5.0.3 h1:ZN+IMa753KfX5hd8vVaMixjnqRZ3y8CuJKRKj1x
 github.com/cenkalti/backoff/v5 v5.0.3/go.mod h1:rkhZdG3JZukswDf7f0cwqPNk4K0sa+F97BxZthm/crw=
 github.com/census-instrumentation/opencensus-proto v0.2.1/go.mod h1:f6KPmirojxKA12rnyqOA5BBL4O983OfeGPqjHWSTneU=
 github.com/certifi/gocertifi v0.0.0-20180118203423-deb3ae2ef261/go.mod h1:GJKEexRPVJrBSOjoqN5VNOIKJ5Q3RViH6eu3puDRwx4=
+github.com/cespare/xxhash/v2 v2.1.1/go.mod h1:VGX0DQ3Q6kWi7AoAeZDth3/j3BFtOZR5XLFGgcrjCOs=
 github.com/cespare/xxhash/v2 v2.3.0 h1:UL815xU9SqsFlibzuggzjXhog7bL6oX9BbNZnL2UFvs=
 github.com/cespare/xxhash/v2 v2.3.0/go.mod h1:VGX0DQ3Q6kWi7AoAeZDth3/j3BFtOZR5XLFGgcrjCOs=
 github.com/charithe/durationcheck v0.0.10 h1:wgw73BiocdBDQPik+zcEoBG/ob8uyBHf2iyoHGPf5w4=