Wait out a registry held still, for up to five minutes, instead of failing the build (issue 457)

The store's nightly collection stops the registry for about a minute and a
half; builds in that window failed on connection refused and failed their
whole plans. A refusal is now waited for with a growing pause, said in the
build's log, and still fails the build past the bound.

internal/builder/registry_wait_test.go

@@ -0,0 +1,154 @@
+package builder
+
+import (
+	"context"
+	"crypto/sha256"
+	"encoding/hex"
+	"net"
+	"net/http"
+	"strings"
+	"sync"
+	"testing"
+	"time"
+)
+
+// A registry held still for a while (novox/hq issue 457): the store's nightly collection stops it for
+// about a minute and a half, and a build in that window was failed, and its whole plan with it, for a
+// pause the mesh itself scheduled. A build waits it out — for a bound longer than the collection
+// holds it — says so in its log, and still fails, loudly, past the bound.
+
+// heldStill is a registry address that refuses every connection until it starts answering after
+// pause, or never when pause is negative.
+func heldStill(t *testing.T, f *fakeRegistry, pause time.Duration) string {
+	t.Helper()
+	handler := f.serve(t).Config.Handler
+	reserved, err := net.Listen("tcp", "127.0.0.1:0")
+	if err != nil {
+		t.Fatal(err)
+	}
+	address := reserved.Addr().String()
+	reserved.Close() // refused from here on: nothing listens
+	if pause < 0 {
+		return address
+	}
+	server := &http.Server{Handler: handler}
+	go func() {
+		time.Sleep(pause)
+		l, err := net.Listen("tcp", address)
+		if err != nil {
+			t.Errorf("cannot answer at %s again: %v", address, err)
+			return
+		}
+		_ = server.Serve(l)
+	}()
+	t.Cleanup(func() { _ = server.Close() })
+	return address
+}
+
+// saying collects what a build says, as the build machine's per-build Said does.
+func saying(t *testing.T) func() []string {
+	t.Helper()
+	var mu sync.Mutex
+	var lines []string
+	was := Said
+	Said = func(step, message string) {
+		mu.Lock()
+		defer mu.Unlock()
+		lines = append(lines, step+": "+message)
+	}
+	t.Cleanup(func() { Said = was })
+	return func() []string {
+		mu.Lock()
+		defer mu.Unlock()
+		return append([]string(nil), lines...)
+	}
+}
+
+// waitingFor shortens the bound and the first pause, so a test waits for milliseconds.
+func waitingFor(t *testing.T, bound time.Duration) {
+	t.Helper()
+	wasBound, wasFirst := registryWait, registryFirstPause
+	registryWait, registryFirstPause = bound, 20*time.Millisecond
+	t.Cleanup(func() { registryWait, registryFirstPause = wasBound, wasFirst })
+}
+
+func TestABuildWaitsForARegistryHeldStillAndGoesOn(t *testing.T) {
+	waitingFor(t, 5*time.Second)
+	said := saying(t)
+	f := &fakeRegistry{}
+	r := Registry{Address: heldStill(t, f, 400*time.Millisecond)}
+	body := []byte("a theme")
+	sum := sha256.Sum256(body)
+	digest := "sha256:" + hex.EncodeToString(sum[:])
+
+	if _, err := r.PublishArchive(context.Background(), "shell/config", body, digest); err != nil {
+		t.Fatalf("a registry refusing for 400ms failed the build: %v", err)
+	}
+	if string(f.blobs[digest]) != "a theme" {
+		t.Fatalf("the registry holds %q", f.blobs[digest])
+	}
+	log := strings.Join(said(), "\n")
+	if !strings.Contains(log, "waits for the registry at "+r.Address) || !strings.Contains(log, "nightly collection") {
+		t.Errorf("the build's log does not say it waited for the registry, and why:\n%s", log)
+	}
+	if !strings.Contains(log, "answers again") {
+		t.Errorf("the build's log does not say the registry came back:\n%s", log)
+	}
+}
+
+func TestABuildFailsLoudlyOnARegistryRefusingPastTheBound(t *testing.T) {
+	waitingFor(t, 300*time.Millisecond)
+	said := saying(t)
+	f := &fakeRegistry{}
+	r := Registry{Address: heldStill(t, f, -1)}
+	body := []byte("a theme")
+	sum := sha256.Sum256(body)
+	digest := "sha256:" + hex.EncodeToString(sum[:])
+
+	started := time.Now()
+	_, err := r.PublishArchive(context.Background(), "shell/config", body, digest)
+	if err == nil {
+		t.Fatal("a registry that never answered published the archive")
+	}
+	if !strings.Contains(err.Error(), "refused every connection for") || !strings.Contains(err.Error(), "connection refused") {
+		t.Errorf("the failure does not say it waited and was refused throughout: %v", err)
+	}
+	if waited := time.Since(started); waited < 300*time.Millisecond {
+		t.Errorf("failed after %s, before the bound", waited)
+	}
+	if log := strings.Join(said(), "\n"); !strings.Contains(log, "waits for the registry") {
+		t.Errorf("the build's log does not say it waited:\n%s", log)
+	}
+}
+
+func TestAnImagePushWaitsForARegistryHeldStill(t *testing.T) {
+	waitingFor(t, 5*time.Second)
+	said := saying(t)
+	pushes := 0
+	run := func(_ context.Context, _ string, name string, args ...string) (string, error) {
+		switch args[0] {
+		case "push":
+			pushes++
+			if pushes < 3 {
+				return "", errorString("docker push: dial tcp 127.0.0.1:5000: connect: connection refused")
+			}
+		case "inspect":
+			return "127.0.0.1:5000/m/server@sha256:abc\n", nil
+		}
+		return "", nil
+	}
+	r := Registry{Address: "127.0.0.1:5000", Run: run}
+	if _, err := r.PublishImage(context.Background(), "local", "m/server"); err != nil {
+		t.Fatalf("a push refused twice failed the build: %v", err)
+	}
+	if pushes != 3 {
+		t.Errorf("pushed %d times, want 3", pushes)
+	}
+	if log := strings.Join(said(), "\n"); !strings.Contains(log, "waits for the registry") {
+		t.Errorf("the build's log does not say it waited:\n%s", log)
+	}
+}
+
+type errorString string
+
+func (e errorString) Error() string { return string(e) }