Merge pull request 'Clone from the forge again when the resolver does not answer, so a passing lookup failure does not fail a build (issue 1773)' (#440) from fix/1773-clone-retries-a-lookup into main

The check's floor of free space reads the disk the test runs on, so
every mesh-controller check failed while its build node had under
20 GiB free, whatever the change (seen in the try of issue 1773's fix).
The replay stubs the free space, as internal/builder's tests do.

cmd/mesh-controller/replay867_test.go

@@ -46,6 +46,11 @@ func replay867(t *testing.T, recheck bool) {
 	if _, err := exec.LookPath("go"); err != nil {
 		t.Skip("no Go toolchain on this machine to build a judge with")
 	}
+	// The check's floor of free space (novox/hq issue 1834) reads the disk the test runs on, which is none of this
+	// replay's business: a build node under the floor failed every mesh-controller check here (issue 1834, note 12).
+	wasFree := builder.FreeBytes
+	builder.FreeBytes = func(string) (uint64, error) { return 500 << 30, nil }
+	t.Cleanup(func() { builder.FreeBytes = wasFree })
 	r := theGroupOfIssue867(t)
 	for _, c := range []struct {
 		what, repo string

internal/builder/builder.go

@@ -241,7 +241,8 @@ func build(ctx context.Context, run Runner, publish Publisher,
 	// A fresh clone every time rather than a fetch into a tree that is already there. A build
 	// that reuses a working tree can succeed because of something a previous build left behind,
 	// and that is a build nobody can reproduce.
-	if _, err := run(ctx, workspace, "git", cloneWith(credentials, "clone", "--quiet", repository, tree)...); err != nil {
+	if err := cloneFromForge(ctx, run, workspace, repository, tree,
+		cloneWith(credentials, "clone", "--quiet", repository, tree), say); err != nil {
 		say("clone", "FAILED: %v", err)
 		return Result{}, fmt.Errorf("cannot clone %s: %w", repository, err)
 	}
@@ -793,7 +794,7 @@ func contextFrom(ctx context.Context, run Runner, workspace, artifact, credentia
 			os.RemoveAll(dir)
 		}
 	}()
-	if _, err := run(ctx, workspace, "git", cloneWith(credentials, "clone", "--quiet", url, dir)...); err != nil {
+	if err := cloneFromForge(ctx, run, workspace, url, dir, cloneWith(credentials, "clone", "--quiet", url, dir), say); err != nil {
 		return "", fmt.Errorf("cannot clone %s: %w", url, err)
 	}
 	if err := recordedWithoutUserinfo(ctx, run, dir, url); err != nil {

internal/builder/check.go

@@ -428,7 +428,8 @@ func Check(ctx context.Context, run Runner, spec CheckSpec, workspace, registry
 	// clone clones a repository and checks out ref; readAt keeps which, by directory.
 	readAt := map[string]string{}
 	clone := func(repository, ref, dir string) error {
-		if _, err := run(ctx, root, "git", cloneWith(credentials, "clone", "--quiet", repository, dir)...); err != nil {
+		if err := cloneFromForge(ctx, run, root, redact.redact(repository), filepath.Join(root, dir),
+			cloneWith(credentials, "clone", "--quiet", repository, dir), say); err != nil {
 			return fmt.Errorf("cannot clone %s: %s", redact.redact(repository), redact.redact(err.Error()))
 		}
 		if err := recordedWithoutUserinfo(ctx, run, filepath.Join(root, dir), repository); err != nil {

internal/builder/clone_lookup.go

@@ -0,0 +1,114 @@
+package builder
+
+import (
+	"context"
+	"fmt"
+	"os"
+	"strings"
+	"time"
+)
+
+// A clone from the forge waits out a resolver that did not answer, for a bounded time (novox/hq issue 1773).
+//
+// **Why.** A build or a check failed now and then on "Could not resolve host: novox.internal" while cloning, between
+// clones that resolved the same name a second before and after, and the whole delivery failed with it. The lookup
+// failing is the resolver's passing fault, not the repository's: nothing reached the forge, so cloning again cannot
+// do anything twice. This is issue 457's shape (a build waits out a registry held still) applied to the name lookup.
+//
+// **Only the lookup.** Any other failure of git — authentication, a repository or a ref that is not there, a 404 —
+// fails at once, as it always did: trying it again would only make a real failure slower.
+//
+// **Bounded, and loud.** Each retry is said in the build's log as the resolver's failure, and past lookupWait the
+// build fails saying the resolver did not answer for that long.
+
+var (
+	// lookupWait is how long a clone waits for a resolver that does not answer.
+	lookupWait = 60 * time.Second
+	// lookupFirstPause is the first pause between tries; each pause doubles, up to lookupMostPause.
+	lookupFirstPause = time.Second
+)
+
+// lookupMostPause is the longest pause between two tries.
+const lookupMostPause = 10 * time.Second
+
+// lookupFailures are what git (through curl) and Go's resolver say when a name did not resolve, in lower case.
+var lookupFailures = []string{
+	"could not resolve host",
+	"temporary failure in name resolution",
+}
+
+// failedLookup is whether an error is a name lookup that failed: git's "Could not resolve host", the system's
+// "Temporary failure in name resolution", or a lookup that timed out.
+func failedLookup(err error) bool {
+	if err == nil {
+		return false
+	}
+	said := strings.ToLower(err.Error())
+	for _, f := range lookupFailures {
+		if strings.Contains(said, f) {
+			return true
+		}
+	}
+	return strings.Contains(said, "lookup ") && strings.Contains(said, "i/o timeout")
+}
+
+// cloneFromForge runs `git clone` of url into dest (git's arguments in args, run from dir), and while it fails on the
+// name lookup, clones again with a growing pause until lookupWait has passed. What a failed try left at dest is
+// removed before the next. Any other failure is returned at once.
+func cloneFromForge(ctx context.Context, run Runner, dir, url, dest string, args []string,
+	say func(step, format string, args ...any)) error {
+	_, err := run(ctx, dir, "git", args...)
+	if !failedLookup(err) {
+		return err
+	}
+	started := time.Now()
+	pause := lookupFirstPause
+	for {
+		elapsed := time.Since(started)
+		left := lookupWait - elapsed
+		if left <= 0 {
+			say("clone", "the resolver did not answer for %s, cloning %s, for %s; the clone fails",
+				urlHost(url), url, elapsed.Round(time.Second))
+			return fmt.Errorf("the resolver did not answer a lookup of %s for %s, cloning %s: %w",
+				urlHost(url), elapsed.Round(time.Millisecond), url, err)
+		}
+		wait := min(pause, left)
+		say("clone", "the resolver did not answer for %s, cloning %s; trying again in %s, for up to %s "+
+			"(novox/hq issue 1773)", urlHost(url), url, wait, lookupWait)
+		select {
+		case <-ctx.Done():
+			return fmt.Errorf("stopped while waiting for the resolver to answer for %s: %w (last: %v)",
+				urlHost(url), ctx.Err(), err)
+		case <-time.After(wait):
+		}
+		pause = min(pause*2, lookupMostPause)
+		if err := os.RemoveAll(dest); err != nil {
+			return err
+		}
+		if _, err = run(ctx, dir, "git", args...); !failedLookup(err) {
+			if err == nil {
+				say("clone", "the resolver answered for %s after %s; the clone worked", urlHost(url),
+					time.Since(started).Round(time.Millisecond))
+			}
+			return err
+		}
+	}
+}
+
+// urlHost is the host (and port) a URL names, or the URL itself when it names none.
+func urlHost(url string) string {
+	rest := url
+	if _, after, ok := strings.Cut(url, "://"); ok {
+		rest = after
+	}
+	if i := strings.IndexAny(rest, "/?#"); i >= 0 {
+		rest = rest[:i]
+	}
+	if i := strings.LastIndex(rest, "@"); i >= 0 {
+		rest = rest[i+1:]
+	}
+	if rest == "" {
+		return url
+	}
+	return rest
+}

internal/builder/clone_lookup_test.go

@@ -0,0 +1,162 @@
+package builder
+
+import (
+	"context"
+	"fmt"
+	"strings"
+	"sync"
+	"testing"
+	"time"
+)
+
+// Issue 1773: a build or a check failed now and then on "Could not resolve host: novox.internal" while cloning from
+// the forge, between clones that resolved the same name, and its whole delivery failed with it. A clone that fails on
+// the name lookup is tried again within a bound, says each retry in the build's log as the resolver's failure, and
+// only past the bound fails, saying the resolver did not answer. Any other failure of git fails at once, as before.
+
+const lookupFailure = "exit status 128\nfatal: unable to access 'http://novox.internal:20000/novox/x.git/': " +
+	"Could not resolve host: novox.internal"
+
+// failingClones is a runner whose first n forge clones fail with failure, then clone as r does; n < 0 fails every one.
+type failingClones struct {
+	r       *recorded
+	n       int
+	failure string
+	clones  int
+}
+
+func (f *failingClones) run(ctx context.Context, dir, name string, args ...string) (string, error) {
+	if name == "git" && isACloneOf(args) {
+		f.clones++
+		if f.n < 0 || f.clones <= f.n {
+			return "", fmt.Errorf("git %s: %s", strings.Join(args, " "), f.failure)
+		}
+	}
+	return f.r.run(ctx, dir, name, args...)
+}
+
+func isACloneOf(args []string) bool {
+	for _, a := range args {
+		if a == "clone" {
+			return true
+		}
+	}
+	return false
+}
+
+// buildLog collects what a build says in its own log.
+func buildLog() (Log, func() []string) {
+	var mu sync.Mutex
+	var lines []string
+	return func(step, message string) {
+			mu.Lock()
+			defer mu.Unlock()
+			lines = append(lines, step+": "+message)
+		}, func() []string {
+			mu.Lock()
+			defer mu.Unlock()
+			return append([]string(nil), lines...)
+		}
+}
+
+const nothingToBuild = `{"module":"x","version":"1"}`
+
+// 1773/AC1: a clone failing twice on the lookup, then working, is tried again, each retry said, and the build goes on.
+func TestACloneThatFailsOnTheLookupIsTriedAgainAndTheBuildGoesOn(t *testing.T) {
+	quickLookups(t)
+	r, workspace := aRepository(t, nothingToBuild, nil)
+	f := &failingClones{r: r, n: 2, failure: lookupFailure}
+	log, said := buildLog()
+	_, err := Build(context.Background(), f.run, r, "http://novox.internal:20000/novox/x.git", "", "", workspace, nil,
+		Npmrc{}, GitCredential{}, log)
+	if err != nil {
+		t.Fatalf("a clone the resolver failed twice, then answered, ended the build: %v", err)
+	}
+	if f.clones != 3 {
+		t.Errorf("the clone ran %d times, want 3 (two lookups failed, the third worked)", f.clones)
+	}
+	retries := 0
+	for _, line := range said() {
+		if strings.Contains(line, "the resolver did not answer") && strings.Contains(line, "novox.internal") {
+			retries++
+		}
+	}
+	if retries != 2 {
+		t.Errorf("the build's log said %d retries as the resolver's failure, want 2:\n%s", retries,
+			strings.Join(said(), "\n"))
+	}
+}
+
+// 1773/AC2: a lookup that keeps failing past the bound fails the build, saying the resolver did not answer.
+func TestACloneWhoseLookupNeverAnswersFailsSayingTheResolverDidNotAnswer(t *testing.T) {
+	quickLookups(t)
+	r, workspace := aRepository(t, nothingToBuild, nil)
+	f := &failingClones{r: r, n: -1, failure: lookupFailure}
+	_, err := Build(context.Background(), f.run, r, "http://novox.internal:20000/novox/x.git", "", "", workspace, nil,
+		Npmrc{}, GitCredential{}, nil)
+	if err == nil {
+		t.Fatal("a clone whose lookup never answered built")
+	}
+	if !strings.Contains(err.Error(), "the resolver did not answer") ||
+		!strings.Contains(err.Error(), "http://novox.internal:20000/novox/x.git") {
+		t.Errorf("the failure does not say the resolver did not answer for the forge's URL: %v", err)
+	}
+	if f.clones < 2 {
+		t.Errorf("the clone ran %d times; a failed lookup is tried again within the bound", f.clones)
+	}
+}
+
+// 1773/AC3: any other failure of git (authentication, a missing repository) is not tried again and fails at once.
+func TestACloneFailingForAnotherReasonIsNotTriedAgain(t *testing.T) {
+	quickLookups(t)
+	for _, failure := range []string{
+		"exit status 128\nfatal: Authentication failed for 'http://novox.internal:20000/novox/x.git/'",
+		"exit status 128\nremote: Not found.\nfatal: repository 'http://novox.internal:20000/novox/x.git/' not found",
+		"exit status 128\nfatal: unable to access 'http://novox.internal:20000/novox/x.git/': The requested URL returned error: 404",
+	} {
+		r, workspace := aRepository(t, nothingToBuild, nil)
+		f := &failingClones{r: r, n: -1, failure: failure}
+		_, err := Build(context.Background(), f.run, r, "http://novox.internal:20000/novox/x.git", "", "", workspace, nil,
+			Npmrc{}, GitCredential{}, nil)
+		if err == nil || !strings.Contains(err.Error(), "cannot clone") {
+			t.Errorf("a clone failing with %q said %v", failure, err)
+		}
+		if f.clones != 1 {
+			t.Errorf("a clone failing with %q ran %d times; it is not a lookup and is not tried again", failure, f.clones)
+		}
+	}
+}
+
+// quickLookups shortens the bound and the pauses, so a test waits for milliseconds.
+func quickLookups(t *testing.T) {
+	t.Helper()
+	wasBound, wasFirst := lookupWait, lookupFirstPause
+	lookupWait, lookupFirstPause = 200*time.Millisecond, 10*time.Millisecond
+	t.Cleanup(func() { lookupWait, lookupFirstPause = wasBound, wasFirst })
+}
+
+// 1773/AC1, 1773/AC3: a check's clones are the same: a failed lookup is tried again, and the failure after it (here
+// an authentication refused) ends the check at once, not tried again.
+func TestACheckCloneTriesAFailedLookupAgain(t *testing.T) {
+	quickLookups(t)
+	clones := 0
+	run := func(_ context.Context, _ string, name string, args ...string) (string, error) {
+		if name == "git" && isACloneOf(args) {
+			clones++
+			if clones <= 2 {
+				return "", fmt.Errorf("git clone: %s", lookupFailure)
+			}
+			return "", fmt.Errorf("git clone: exit status 128\nfatal: Authentication failed")
+		}
+		return "", nil
+	}
+	_, err := Check(context.Background(), run, CheckSpec{ID: "build-1", Owner: "novox", Repo: "x", Number: 1,
+		Repository: "http://novox.internal:20000/novox/x.git", Ref: "abc"}, t.TempDir(), "registry.invalid",
+		GitCredential{}, nil)
+	if err == nil || !strings.Contains(err.Error(), "cannot clone") || !strings.Contains(err.Error(), "Authentication failed") {
+		t.Fatalf("the check said %v", err)
+	}
+	if clones != 3 {
+		t.Errorf("the check's clone ran %d times, want 3: two failed lookups, then the refusal, not tried again", clones)
+	}
+}