Say what rotate printed when the served rotation test fails (issue 1945)

cmd/mesh-controller/composed_served_integration_test.go

@@ -10,6 +10,7 @@ import (
 	"net/url"
 	"os"
 	"path/filepath"
+	"strings"
 	"testing"
 	"time"
 
@@ -434,13 +435,24 @@ func TestServedADoneKeyIsComposedAndGranted(t *testing.T) {
 func TestServedARotationRewritesOnlyTheCompositionsThatUseIt(t *testing.T) {
 	m := aServedMesh(t)
 	before := map[string]map[string]uint64{"anchor": m.revisions(t, "anchor"), "laptop": m.revisions(t, "laptop")}
-	if err := rotateCommand(t.Context(), []string{"postgres-database"}); err != nil {
-		t.Fatalf("rotate: %v", err)
+	holders, _ := m.open.inventory.HoldersOf(t.Context(), "postgres-database", "")
+	said, err := capturedOutput(func() error { return rotateCommand(t.Context(), []string{"postgres-database"}) })
+	if err != nil {
+		t.Fatalf("rotate: %v\n%s", err, said)
 	}
+	t.Logf("rotate said (holders before: %+v):\n%s", holders, said)
+	defer func() {
+		if t.Failed() {
+			t.Logf("rotate said:\n%s", said)
+		}
+	}()
 	boardKey, _ := sdkdelivery.ComposedKey("laptop", "board", fpOf('b'))
 	storeKey, _ := sdkdelivery.ComposedKey("anchor", "store", fpOf('a'))
 	// The board's sealed credential file is new: its composition moves with the rotation.
-	m.waitFor(t, nil, "laptop", boardKey, before["laptop"][boardKey])
+	if rev := m.waitForOrSay(t, "laptop", boardKey, before["laptop"][boardKey]); rev == 0 {
+		t.Fatalf("the board's composition did not move within a minute after the rotation; rotate said (holders before: %+v):\n%s\n%s",
+			holders, said, m.whatIsThere(t, "laptop"))
+	}
 	moved := map[string]bool{}
 	for node, was := range before {
 		for k, rev := range m.revisions(t, node) {
@@ -461,3 +473,46 @@ func TestServedARotationRewritesOnlyTheCompositionsThatUseIt(t *testing.T) {
 		t.Errorf("%d declarations were sent", n)
 	}
 }
+
+// waitForOrSay is waitFor that answers 0 instead of failing, for a caller that says more.
+func (m *servedMesh) waitForOrSay(t *testing.T, node, key string, after uint64) uint64 {
+	t.Helper()
+	bucket, _ := sdkdelivery.ComposedBucketFor(node)
+	deadline := time.Now().Add(time.Minute)
+	for time.Now().Before(deadline) {
+		if kv, err := m.controller.KeyValue(t.Context(), bucket); err == nil {
+			if e, err := kv.Get(t.Context(), key); err == nil && e.Revision() > after {
+				return e.Revision()
+			}
+		}
+		time.Sleep(200 * time.Millisecond)
+	}
+	return 0
+}
+
+// capturedOutput runs act with this process's standard output captured, and answers what it printed.
+func capturedOutput(act func() error) (string, error) {
+	r, w, err := os.Pipe()
+	if err != nil {
+		return "", act()
+	}
+	was := os.Stdout
+	os.Stdout = w
+	done := make(chan string)
+	go func() {
+		var b strings.Builder
+		buf := make([]byte, 4096)
+		for {
+			n, err := r.Read(buf)
+			b.Write(buf[:n])
+			if err != nil {
+				break
+			}
+		}
+		done <- b.String()
+	}()
+	actErr := act()
+	os.Stdout = was
+	w.Close()
+	return <-done, actErr
+}