package builder import ( "context" "crypto/sha256" "encoding/hex" "errors" "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, 100*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 100ms 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, 100*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 < 100*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) } // 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) } }