Measure the iframe reveal budgets from inside the page (#2189)

The three reveal tests timed their budgets from before `page.Goto`, so a
slow navigation was spent against a window that belongs to the iframe. In
`TestIframe_StaysHiddenUntilTheDocumentReportsInited` that made the test
vacuous rather than flaky: on a navigation between 2.5 and 5 seconds the
loop bounding the visibility assertion had no budget left, ran zero times,
and the test passed having asserted nothing. Reproduced by delaying the
demo document by three seconds, where the assertion ran 0 times before and
runs 23 after. The timeout test had the mirror of it, with navigation
counting toward the lower bound that exists to catch a shortened fallback.

An init script now records, in the page, when the widget's iframe element
enters the document and when its visibility first flips. `create-iframe.ts`
arms its fallback a moment earlier, on the detached element, so these read
a shade short and every bound is conservative in the same direction.

Both bounds were also wider than the thing they guard. The hidden window
now runs almost to the fallback rather than half of it, and the lower bound
sits just under it rather than at three quarters, which a fallback
shortened to four seconds used to clear.

CI reruns a failing test once rather than failing the build on the first
flake. A browser suite has a floor no amount of care removes, and one flake
failing the build is what stops people trusting the suite. Once rather than
twice, because a rerun stops at the first pass and each further attempt
only widens the window where a real intermittent regression is absorbed.
What needed a rerun is written to a report and uploaded with the traces,
which are kept whether or not the job went green: a run that recovered on
the rerun is exactly the one whose evidence used to be discarded.

.github/workflows/e2e-tests.yml

@@ -59,7 +59,9 @@ jobs:
   tests:
     name: Tests
     needs: vet
-    timeout-minutes: 30
+    # generous against the docker build plus two go test invocations: a job cancelled on
+    # timeout skips its own failure steps, so the run would end with neither logs nor traces
+    timeout-minutes: 45
     runs-on: ubuntu-latest
     permissions:
       contents: read
@@ -89,18 +91,43 @@ jobs:
       - name: Build & start the stack
         run: COMPOSE_DOCKER_CLI_BUILD=1 DOCKER_BUILDKIT=1 docker compose -f compose-e2e-test.yml up -d --build --quiet-pull --wait
 
+      - name: Install gotestsum
+        run: go install gotest.tools/gotestsum@v1.13.0
+
+      # each rerun is its own `go test` process carrying the same timeout, so the ceiling is
+      # 8m for the first attempt plus 4 x 8m of reruns, inside the job's 45. a job cancelled on
+      # timeout skips its own upload steps, which is the one outcome worth designing against.
+      # four failures covers one test failing across all three engines, counted as its three
+      # subtests plus their parent; more than that is a regression and should not be rerun.
+      # a browser suite has a flake floor no amount of care removes, and one flake failing the
+      # build is what makes people stop trusting it. one rerun, not two: a rerun stops at the
+      # first pass, so each further attempt only widens the window in which a real intermittent
+      # regression is absorbed. what needed a rerun is written to a report and uploaded, since
+      # a green job is a job nobody reads the log of
       - name: Run e2e
-        run: cd e2e && go test -tags=e2e -count 1 -timeout 20m -v ./...
+        # shared across the rerun so it exercises the same threads as the attempt that failed
+        env:
+          E2E_RUN_ID: ${{ github.run_id }}-${{ github.run_attempt }}
+        run: |
+          cd e2e && gotestsum \
+            --rerun-fails=1 \
+            --rerun-fails-max-failures=4 \
+            --rerun-fails-report=rerun-report.txt \
+            --packages=./... \
+            --format standard-verbose \
+            -- -tags=e2e -count 1 -timeout 8m
 
       - name: Server logs on failure
         if: failure()
         run: docker compose -f compose-e2e-test.yml logs --tail=200
 
-      - name: Upload browser traces
-        if: failure()
+      - name: Upload browser traces and any rerun report
+        if: always()
         uses: actions/upload-artifact@v7
         with:
           name: playwright-traces
-          path: e2e/traces/
+          path: |
+            e2e/traces/
+            e2e/rerun-report.txt
           retention-days: 30
           if-no-files-found: ignore

e2e/README.md

@@ -43,7 +43,9 @@ The build tag keeps these out of `go test ./...`; nothing runs without `-tags=e2
 
 ## When something fails
 
-A failed test writes a Playwright trace to `e2e/traces/`, which CI uploads as an artifact. Open one with `npx playwright show-trace e2e/traces/<name>.zip`.
+A failed test writes a Playwright trace to `e2e/traces/`, which CI uploads as an artifact whether or not the job went green. Open one with `npx playwright show-trace e2e/traces/<name>.zip`.
+
+CI runs the suite through `gotestsum` and gives a failing test one rerun, so a test that fails and then passes leaves the job green. That is the case worth looking at: it is named in `rerun-report.txt`, uploaded beside the traces. Only attempts that failed leave a trace, and they do not overwrite each other, so a flake leaves exactly one to open. `make e2e` locally does not rerun anything, so a test red on a laptop and green in CI is a flake with a report to read rather than a disagreement.
 
 Beyond that: `docker compose -f compose-e2e-test.yml logs` for the server side, and mailpit's web UI on <http://127.0.0.1:8025> for anything email.
 

e2e/e2e_test.go

@@ -72,8 +72,11 @@ var (
 	extraBrowsers   = map[string]playwright.Browser{}
 	extraBrowsersMu sync.Mutex
 
-	// distinguishes this run's threads from those a previous run left in the database
-	runID = fmt.Sprintf("%d", time.Now().UnixNano())
+	// distinguishes this run's threads from those a previous run left in the database.
+	// a rerun is a fresh process, so without E2E_RUN_ID it would get its own threads and a
+	// failure caused by ordering or by state an earlier test left behind would pass on the
+	// second attempt whatever the code did
+	runID = firstNonEmpty(os.Getenv("E2E_RUN_ID"), fmt.Sprintf("%d", time.Now().UnixNano()))
 
 	authGate     sync.Mutex
 	lastAuthCall time.Time
@@ -176,6 +179,15 @@ func ensureStack() error {
 	return nil
 }
 
+func firstNonEmpty(values ...string) string {
+	for _, v := range values {
+		if v != "" {
+			return v
+		}
+	}
+	return ""
+}
+
 // stackReady reports whether every service the suite needs answers
 func stackReady(timeout time.Duration) bool {
 	for _, url := range []string{
@@ -238,6 +250,10 @@ func newPageOn(t *testing.T, b playwright.Browser) playwright.Page {
 	ctx, err := b.NewContext()
 	require.NoError(t, err)
 
+	// the reveal timers start when the iframe element is created, so the tests that bound
+	// them have to measure from there rather than from anything this process can time
+	require.NoError(t, ctx.AddInitScript(playwright.Script{Content: playwright.String(iframeMarkScript)}))
+
 	tracing := ctx.Tracing().Start(playwright.TracingStartOptions{
 		Screenshots: playwright.Bool(true),
 		Snapshots:   playwright.Bool(true),
@@ -255,8 +271,11 @@ func newPageOn(t *testing.T, b playwright.Browser) playwright.Page {
 			}
 			// say so rather than swallowing it: this runs only on a test that already failed,
 			// and a silently missing trace is what the reader goes looking for
+			// the pid distinguishes attempts: a rerun is a fresh process that shares runID
+			// with the attempt it is retrying and restarts its own counter, so without it the
+			// rerun would overwrite the trace of the attempt that actually failed
 			name := strings.ReplaceAll(t.Name(), "/", "-")
-			path := filepath.Join(traceDir, fmt.Sprintf("%s-%d.zip", name, seq))
+			path := filepath.Join(traceDir, fmt.Sprintf("%s-%d-%d.zip", name, os.Getpid(), seq))
 			if serr := ctx.Tracing().Stop(path); serr != nil {
 				t.Logf("could not write the trace to %s: %v", path, serr)
 			}

e2e/iframe_test.go

@@ -3,6 +3,7 @@
 package e2e
 
 import (
+	"math"
 	"regexp"
 	"testing"
 	"time"
@@ -102,23 +103,111 @@ const (
 
 // openWithBlockedIframeDoc loads the demo page with the widget document aborted, so the
 // iframe element exists but never reports itself inited
-func openWithBlockedIframeDoc(t *testing.T, page playwright.Page) time.Time {
+func openWithBlockedIframeDoc(t *testing.T, page playwright.Page) {
 	t.Helper()
 	require.NoError(t, page.Route(regexp.MustCompile(`/web/iframe\.html`), func(route playwright.Route) {
 		_ = route.Abort()
 	}))
 
-	// the gate's sleep happens before the iframe exists, so it must not count against the
-	// reveal budgets: start the clock with the navigation
 	pauseForAuthLimit()
-	start := time.Now()
 	_, err := page.Goto(renderURL(t))
 	require.NoError(t, err)
 	require.NoError(t, page.Locator("#remark42 iframe").WaitFor(playwright.LocatorWaitForOptions{
 		State:   playwright.WaitForSelectorStateAttached,
 		Timeout: playwright.Float(float64(waitTimeout.Milliseconds())),
 	}))
-	return start
+}
+
+// iframeMarkScript records, in the page, when the widget's iframe element is created and when
+// it is first revealed. create-iframe.ts starts its fallback timer at creation, and neither
+// moment can be timed from outside the page: navigation alone can outlast the budgets, which
+// would let a bound pass without the assertion it guards ever running
+const iframeMarkScript = `(() => {
+  // top document only. playwright runs an init script in every frame, and inside the widget
+  // document the selector below never matches, so the observer would run for the life of the
+  // busiest DOM in the suite without ever finding a reason to disconnect
+  if (window.top !== window) { return; }
+  if (window.__r42Marks) { return; }
+  window.__r42Marks = {};
+  const watch = (frame) => {
+    if (window.__r42Marks.created !== undefined) { return; }
+    window.__r42Marks.created = performance.now();
+    const style = new MutationObserver(() => { seen(); });
+    const seen = () => {
+      if (window.__r42Marks.revealed === undefined && frame.style.visibility === 'visible') {
+        window.__r42Marks.revealed = performance.now();
+        style.disconnect();
+      }
+    };
+    style.observe(frame, {attributes: true, attributeFilter: ['style']});
+    seen();
+  };
+  // document rather than documentElement: an init script runs before the root element
+  // exists, and observing null would throw before any of this could take effect
+  const tree = new MutationObserver(() => { scan(); });
+  const scan = () => {
+    const frame = document.querySelector('#remark42 iframe');
+    if (frame) { watch(frame); tree.disconnect(); }
+  };
+  tree.observe(document, {childList: true, subtree: true});
+  document.addEventListener('DOMContentLoaded', scan);
+  // and stop looking once the page has loaded. embed.ts creates the frame no later than
+  // DOMContentLoaded, so a page still without one never will have one, and the suite opens
+  // several: the widget document itself, the counter page and the last-comments page, whose
+  // own rendering would otherwise keep this observer busy for the life of the page
+  window.addEventListener('load', () => { tree.disconnect(); });
+  scan();
+})()`
+
+// evalMillis reads a number out of the page. it takes int as well as float64, because the
+// driver hands back whichever the value happens to be and a bare float64 assertion turns an
+// integral sentinel into a silent zero
+func evalMillis(t *testing.T, page playwright.Page, script string) float64 {
+	t.Helper()
+	v, err := page.Evaluate(script)
+	require.NoError(t, err)
+
+	switch n := v.(type) {
+	case float64:
+		require.False(t, math.IsNaN(n) || math.IsInf(n, 0), "got a non-finite number from the page")
+		return n
+	case int:
+		return float64(n)
+	default:
+		t.Fatalf("expected a number from the page, got %T (%v)", v, v)
+		return 0
+	}
+}
+
+// iframeAge is how long the iframe element has existed, measured in the page.
+//
+// the mark is taken when the element is inserted, while create-iframe.ts starts its fallback
+// a moment earlier, when the detached element is built. the gap is one task, so every age
+// here reads slightly short: bounds below a budget are conservative, bounds above it are not
+func iframeAge(t *testing.T, page playwright.Page) time.Duration {
+	t.Helper()
+	ms := evalMillis(t, page, `() => window.__r42Marks && window.__r42Marks.created !== undefined
+		? performance.now() - window.__r42Marks.created : -1`)
+	require.GreaterOrEqual(t, ms, float64(0), "the iframe element has not been created yet")
+	return time.Duration(ms) * time.Millisecond
+}
+
+// revealDelay is how long after creation the iframe was revealed, measured in the page. it
+// reports false while the frame is still hidden
+func revealDelay(t *testing.T, page playwright.Page) (time.Duration, bool) {
+	t.Helper()
+	ms := evalMillis(t, page, `() => {
+		const m = window.__r42Marks;
+		if (!m || m.created === undefined) { return -2; }
+		return m.revealed !== undefined ? m.revealed - m.created : -1;
+	}`)
+	// -2 is the harness, -1 is the widget. without the distinction a broken selector reads as
+	// "the frame was never revealed" and the failure names the wrong thing
+	require.NotEqual(t, float64(-2), ms, "the iframe element was never seen by the page marks")
+	if ms < 0 {
+		return 0, false
+	}
+	return time.Duration(ms) * time.Millisecond, true
 }
 
 func iframeVisibility(t *testing.T, page playwright.Page) string {
@@ -134,17 +223,23 @@ func iframeVisibility(t *testing.T, page playwright.Page) string {
 
 func TestIframe_StaysHiddenUntilTheDocumentReportsInited(t *testing.T) {
 	forEachEngine(t, func(t *testing.T, page playwright.Page) {
-		start := openWithBlockedIframeDoc(t, page)
+		openWithBlockedIframeDoc(t, page)
 
-		// sampling once would pass against a widget that revealed a frame moments later, so
-		// hold the assertion for a stretch of the window in which it must stay hidden
-		for time.Since(start) < revealTimeout/2 {
+		// unconditional: the loop below is bounded by the frame's own age, and on a slow
+		// enough load that bound can already be spent, which would leave the test asserting
+		// nothing at all about visibility
+		require.Equal(t, "hidden", iframeVisibility(t, page))
+
+		// then hold it for almost the whole fallback window. stopping halfway would only prove
+		// the fallback is not shorter than that, and a widget that revealed on anything other
+		// than `inited` would still pass. measured from the element's creation, since that is
+		// when the fallback it must not have used starts counting
+		for iframeAge(t, page) < revealTimeout-500*time.Millisecond {
 			require.Equal(t, "hidden", iframeVisibility(t, page))
 			time.Sleep(100 * time.Millisecond)
 		}
-		// a slow run could have let the fallback fire, which would make the assertion above
-		// pass or fail for the wrong reason. fail loudly instead of flaking
-		assert.Less(t, time.Since(start), revealTimeout)
+		_, revealed := revealDelay(t, page)
+		assert.False(t, revealed, "the frame was revealed before its document reported inited")
 	})
 }
 
@@ -165,14 +260,21 @@ func forEachEngine(t *testing.T, body func(t *testing.T, page playwright.Page))
 func TestIframe_IsRevealedByTheInitedMessage(t *testing.T) {
 	forEachEngine(t, func(t *testing.T, page playwright.Page) {
 		pauseForAuthLimit()
-		start := time.Now()
 		_, err := page.Goto(renderURL(t))
 		require.NoError(t, err)
 
-		eventually(t, messageRevealBudget, "iframe was not revealed by the inited message", func() bool {
-			return iframeVisibility(t, page) == "visible"
+		eventually(t, waitTimeout, "iframe was never revealed", func() bool {
+			_, ok := revealDelay(t, page)
+			return ok
 		})
-		assert.Less(t, time.Since(start), revealTimeout)
+
+		// the reveal has to have come from the message rather than the fallback, and the two
+		// are only distinguishable against the frame's own clock: navigation can outlast the
+		// whole 5s window without the widget being at fault
+		delay, ok := revealDelay(t, page)
+		require.True(t, ok, "the frame reported no reveal at all")
+		assert.Less(t, delay, messageRevealBudget,
+			"the reveal was slow enough to have come from the fallback rather than the message")
 		waitVisible(t, page.Locator("#remark42 iframe"))
 	})
 }
@@ -181,14 +283,22 @@ func TestIframe_IsRevealedByTheInitedMessage(t *testing.T) {
 // visibility assertion on geometry would fail. Assert the property the fallback actually sets.
 func TestIframe_IsRevealedByTheTimeoutWhenInitedNeverArrives(t *testing.T) {
 	forEachEngine(t, func(t *testing.T, page playwright.Page) {
-		start := openWithBlockedIframeDoc(t, page)
+		openWithBlockedIframeDoc(t, page)
+
+		eventually(t, revealTimeout*2, "fallback never revealed the iframe", func() bool {
+			_, ok := revealDelay(t, page)
+			return ok
+		})
 
 		// and not before it: without a lower bound, shortening the fallback to a value that
-		// defeats its purpose would still pass
-		eventually(t, revealTimeout*2, "fallback never revealed the iframe", func() bool {
-			return iframeVisibility(t, page) == "visible"
-		})
-		assert.Greater(t, time.Since(start), revealTimeout*3/4,
+		// defeats its purpose would still pass. against the frame's own clock, so that a slow
+		// navigation cannot be mistaken for the timer having run
+		// close to the fallback rather than three quarters of it: measured in the page there is
+		// no navigation to make room for, and a wider floor tolerates a fallback shortened
+		// enough to defeat its purpose
+		delay, ok := revealDelay(t, page)
+		require.True(t, ok, "the frame reported no reveal at all")
+		assert.Greater(t, delay, revealTimeout-500*time.Millisecond,
 			"the reveal came too early to have been the fallback timer")
 	})
 }