bastion 0.53.2

client-go/backuphash_progress_test.go

@@ -0,0 +1,184 @@
+package main
+
+// Gate: a read of a backup for its digest counts as stuck only when it has
+// gone without an answer for its bound, not when the whole file takes longer
+// than that. A large backup on a slow disk whose reads keep returning refuses
+// no push from its folder; a read that stops answering still does.
+
+import (
+	"bytes"
+	"os"
+	"path/filepath"
+	"strings"
+	"sync"
+	"sync/atomic"
+	"testing"
+	"time"
+)
+
+const hashTestBound = 300 * time.Millisecond
+
+// slowHash makes the hashing job read one file a byte at a time, each read
+// taking pace: a disk that answers, slowly. After stallAfter reads (when not
+// zero) its reads stop answering until finish. finish lets it read at full
+// speed.
+type slowHash struct {
+	reads atomic.Int64
+	fast  chan struct{}
+	once  sync.Once
+	logMu sync.Mutex
+	logs  []string
+}
+
+func slowHashReads(t *testing.T, file string, pace time.Duration, stallAfter int64) *slowHash {
+	t.Helper()
+	s := &slowHash{fast: make(chan struct{})}
+	hashMu.Lock()
+	prevBound, prevRead := hashJobTimeout, hashRead
+	hashJobTimeout = hashTestBound
+	hashRead = func(f *os.File, p []byte) (int, error) {
+		if f.Name() != file {
+			return prevRead(f, p)
+		}
+		select {
+		case <-s.fast:
+			return prevRead(f, p)
+		default:
+		}
+		if n := s.reads.Add(1); stallAfter > 0 && n > stallAfter {
+			<-s.fast
+			return prevRead(f, p)
+		}
+		time.Sleep(pace)
+		return prevRead(f, p[:1])
+	}
+	hashMu.Unlock()
+	quiet := opMaskLog
+	opMaskLog = func(format string, a ...any) {
+		s.logMu.Lock()
+		defer s.logMu.Unlock()
+		s.logs = append(s.logs, format)
+	}
+	t.Cleanup(func() {
+		s.finish()
+		readsIdle(t)
+		eventually(t, "the hashing job ends", func() bool {
+			hashMu.Lock()
+			defer hashMu.Unlock()
+			return !hashRunning
+		})
+		hashMu.Lock()
+		hashJobTimeout, hashRead = prevBound, prevRead
+		hashMu.Unlock()
+		opMaskLog = quiet
+	})
+	return s
+}
+
+func (s *slowHash) finish() { s.once.Do(func() { close(s.fast) }) }
+
+func (s *slowHash) logged(part string) bool {
+	s.logMu.Lock()
+	defer s.logMu.Unlock()
+	for _, l := range s.logs {
+		if strings.Contains(l, part) {
+			return true
+		}
+	}
+	return false
+}
+
+func hashReadInFlight(dir string) bool {
+	backupReadMu.Lock()
+	defer backupReadMu.Unlock()
+	r := backupReads[dir]
+	return r != nil && !r.hash.IsZero()
+}
+
+// A backup B in a folder that answers, slowly: reading it for its digest
+// takes many times the bound, its reads returning all along. A push of
+// another backup A in that folder starts and reads A while B is still being
+// read.
+func TestASlowHashThatKeepsAnsweringRefusesNoPushFromItsFolder(t *testing.T) {
+	stubPublicDNS(t)
+	shortPushStall(t)
+	readsIdle(t)
+	root := t.TempDir()
+	rel, _ := pushFixture(t, root, []byte(strings.Repeat("a backup ", 1000)))
+	big := filepath.Join(root, "20260101T000000Z.tar.zst.age")
+	body := bytes.Repeat([]byte("big new backup "), 300)
+	if err := os.WriteFile(big, body, 0o600); err != nil {
+		t.Fatal(err)
+	}
+	s := slowHashReads(t, big, 30*time.Millisecond, 0)
+
+	requestHash(big)
+	eventually(t, "the hashing job reads the big backup", func() bool { return s.reads.Load() > 0 })
+	time.Sleep(3 * hashTestBound)
+	if what, stuck := folderStuck(root, time.Now(), pushStallBound(), hashBound()); stuck {
+		t.Fatalf("a hash whose reads keep returning made its folder stuck: %s", what)
+	}
+	// Named with a digest that is not A's, the push reads all of A and fails
+	// on the comparison, sending nothing.
+	id := pushStarted(t, root, rel, strings.Repeat("ab", 32))
+	if st := awaitPush(t, root, id); st["state"] != "failed" || !strings.Contains(st["error"], "sha256 differs") {
+		t.Fatalf("a push from a folder being hashed slowly did not read its file: %v", st)
+	}
+	if !hashReadInFlight(root) {
+		t.Fatal("the slow hash ended before the push read its file")
+	}
+	if !s.logged("is taking more than") || s.logged("has not answered") {
+		t.Fatal("the log of a slow hash does not say it is slow, or says it stopped answering")
+	}
+
+	s.finish()
+	awaitHash(t, big, sha(body), "the slow hash's digest was not kept")
+}
+
+// A read for a digest that answers for a while and then goes without an
+// answer for the bound still makes its folder stuck: a push there is refused
+// with the sentence about the digest, and the read counts toward the cap.
+func TestAHashWithNoAnswerForTheBoundStillMarksItsFolderStuck(t *testing.T) {
+	stubPublicDNS(t)
+	shortPushStall(t)
+	readsIdle(t)
+	root := t.TempDir()
+	rel, sum := pushFixture(t, root, []byte(strings.Repeat("a backup ", 1000)))
+	big := filepath.Join(root, "20260101T000000Z.tar.zst.age")
+	body := bytes.Repeat([]byte("big new backup "), 300)
+	if err := os.WriteFile(big, body, 0o600); err != nil {
+		t.Fatal(err)
+	}
+	s := slowHashReads(t, big, 30*time.Millisecond, 20)
+
+	requestHash(big)
+	// Past the bound in all, its reads answering: not stuck.
+	eventually(t, "the hashing job reads past the bound", func() bool { return s.reads.Load() >= 15 })
+	if what, stuck := folderStuck(root, time.Now(), pushStallBound(), hashBound()); stuck {
+		t.Fatalf("a hash whose reads keep returning made its folder stuck: %s", what)
+	}
+
+	// Then no answer: stuck, and a push is refused.
+	stuckPast(t, root)
+	_, errOut, code := startPush(t, root, rel, sum)
+	if code == 0 || !strings.Contains(errOut,
+		"backup_push: the folder of "+rel+" has not answered the reading of a backup for its digest for more than") {
+		t.Fatalf("a push in a folder whose hashing read stopped answering: %d %s", code, errOut)
+	}
+	backupReadMu.Lock()
+	n := stuckReadsLocked(time.Now(), pushStallBound(), hashBound())
+	backupReadMu.Unlock()
+	if n != 1 {
+		t.Fatalf("%d stuck reads counted toward the cap; want the hashing read's 1", n)
+	}
+	eventually(t, "the log says the read has not answered", func() bool { return s.logged("has not answered") })
+
+	// When it answers again its digest is kept, and a push starts.
+	s.finish()
+	awaitHash(t, big, sha(body), "the stalled hash's digest was not kept when it answered")
+	readsIdle(t)
+	id := pushStarted(t, root, rel, strings.Repeat("ab", 32))
+	if st := awaitPush(t, root, id); st["state"] != "failed" || !strings.Contains(st["error"], "sha256 differs") {
+		t.Fatalf("a push once the hashing read answered: %v", st)
+	}
+}