Merge pull request 'Wait out a resolver that does not answer in a build's registry step, and say it was the resolver (issue 1748)' (#447) from fix/1748-registry-wait-retries-a-lookup into main

internal/builder/registry_wait.go

@@ -45,21 +45,37 @@ func refused(err error) bool {
 	return err != nil && (errors.Is(err, syscall.ECONNREFUSED) || strings.Contains(err.Error(), "connection refused"))
 }
 
-// waitForRegistry runs try, and while it fails because the registry at address refuses connections,
-// tries again with a growing pause until registryWait has passed. what names the call, for the log.
+// waitedFor is whether an error is one a build waits out: a refused connection, or a lookup of the registry's name
+// that the resolver did not answer (novox/hq issue 1748; failedLookup, from issue 1773, says which).
+func waitedFor(err error) bool { return refused(err) || failedLookup(err) }
+
+// waitForRegistry runs try, and while it fails because the registry at address refuses connections, or the
+// resolver does not answer a lookup of its name, tries again with a growing pause until registryWait has passed. what names the call, for the log.
 func waitForRegistry(ctx context.Context, address, what string, try func() error) error {
 	err := try()
-	if !refused(err) {
+	if !waitedFor(err) {
 		return err
 	}
 	started := time.Now()
 	pause := registryFirstPause
-	tell("registry", "%s: refused; the build waits for the registry at %s, for up to %s — it is held still while "+
-		"the store's nightly collection runs, about a minute and a half (novox/hq issue 457)",
-		what, address, registryWait)
+	if failedLookup(err) {
+		tell("registry", "%s: the resolver did not answer a lookup of the registry's name (%v); the build waits, "+
+			"for up to %s (novox/hq issue 1748)", what, err, registryWait)
+	} else {
+		tell("registry", "%s: refused; the build waits for the registry at %s, for up to %s — it is held still while "+
+			"the store's nightly collection runs, about a minute and a half (novox/hq issue 457)",
+			what, address, registryWait)
+	}
 	for {
 		left := registryWait - time.Since(started)
 		if left <= 0 {
+			if failedLookup(err) {
+				tell("registry", "%s: the resolver still did not answer a lookup of the registry at %s after %s; the build fails",
+					what, address, time.Since(started).Round(time.Second))
+				return fmt.Errorf("the resolver did not answer a lookup of the registry at %s for %s, so it is the "+
+					"resolver, not the registry, that is down: %w",
+					address, time.Since(started).Round(time.Millisecond), err)
+			}
 			tell("registry", "%s: the registry at %s still refuses after %s; the build fails", what, address,
 				time.Since(started).Round(time.Second))
 			return fmt.Errorf("the registry at %s refused every connection for %s, longer than its nightly "+
@@ -73,7 +89,7 @@ func waitForRegistry(ctx context.Context, address, what string, try func() error
 		case <-time.After(wait):
 		}
 		pause = min(pause*2, registryMostPause)
-		if err = try(); !refused(err) {
+		if err = try(); !waitedFor(err) {
 			// Said as it is: the registry answering is only the build going on when the call worked.
 			if err == nil {
 				tell("registry", "%s: the registry at %s answers again after %s; the build goes on", what, address,

internal/builder/registry_wait_test.go

@@ -4,6 +4,7 @@ import (
 	"context"
 	"crypto/sha256"
 	"encoding/hex"
+	"errors"
 	"net"
 	"net/http"
 	"strings"
@@ -152,3 +153,67 @@ func TestAnImagePushWaitsForARegistryHeldStill(t *testing.T) {
 type errorString string
 
 func (e errorString) Error() string { return string(e) }
+
+// A resolver that does not answer for a moment (novox/hq issue 1748): a lookup of the registry's name that
+// timed out failed the build at once, though the same name resolved a second later.
+
+const lookupTimeout = "Head \"http://novox.internal:5100/v2/x/blobs/sha256:1\": dial tcp: lookup novox.internal on 10.10.0.3:53: " +
+	"read udp 10.10.0.3:44790->10.10.0.3:53: i/o timeout"
+
+type lookupTimedOut struct{}
+
+func (lookupTimedOut) Error() string { return lookupTimeout }
+
+func TestABuildWaitsOutAResolverThatDoesNotAnswerAndGoesOn(t *testing.T) { // 1748/AC1
+	waitingFor(t, 5*time.Second)
+	said := saying(t)
+	calls := 0
+	err := waitForRegistry(context.Background(), "novox.internal:5100", "HEAD /v2/x", func() error {
+		calls++
+		if calls < 3 {
+			return lookupTimedOut{}
+		}
+		return nil
+	})
+	if err != nil {
+		t.Fatalf("a lookup timing out twice failed the build: %v", err)
+	}
+	if calls != 3 {
+		t.Errorf("tried %d times, want 3", calls)
+	}
+	log := strings.Join(said(), "\n")
+	if !strings.Contains(log, "resolver did not answer") || !strings.Contains(log, "answers again") {
+		t.Errorf("the build's log does not say the resolver was waited for, and that it came back:\n%s", log)
+	}
+}
+
+func TestABuildFailsNamingTheResolverWhenItDoesNotAnswerPastTheBound(t *testing.T) { // 1748/AC2
+	waitingFor(t, 100*time.Millisecond)
+	saying(t)
+	started := time.Now()
+	err := waitForRegistry(context.Background(), "novox.internal:5100", "HEAD /v2/x", func() error { return lookupTimedOut{} })
+	if err == nil {
+		t.Fatal("a resolver that never answered let the build go on")
+	}
+	if !strings.Contains(err.Error(), "resolver did not answer") || !strings.Contains(err.Error(), "i/o timeout") {
+		t.Errorf("the failure does not name the resolver: %v", err)
+	}
+	if strings.Contains(err.Error(), "refused every connection") {
+		t.Errorf("the failure blames a refusal: %v", err)
+	}
+	if waited := time.Since(started); waited < 100*time.Millisecond {
+		t.Errorf("failed after %s, before the bound", waited)
+	}
+}
+
+func TestAnErrorThatIsNeitherARefusalNorALookupFailsAtOnce(t *testing.T) { // 1748/AC3
+	waitingFor(t, 5*time.Second)
+	calls := 0
+	err := waitForRegistry(context.Background(), "novox.internal:5100", "HEAD /v2/x", func() error {
+		calls++
+		return errors.New("401 unauthorized")
+	})
+	if err == nil || calls != 1 {
+		t.Fatalf("err %v after %d calls, want a failure at once", err, calls)
+	}
+}