diff --git a/.github/workflows/e2e-tests.yml b/.github/workflows/e2e-tests.yml index 3e3b5e94..d83a81ba 100644 --- a/.github/workflows/e2e-tests.yml +++ b/.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 diff --git a/e2e/README.md b/e2e/README.md index 04cb1129..19c6dc6b 100644 --- a/e2e/README.md +++ b/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/.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/.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 for anything email. diff --git a/e2e/e2e_test.go b/e2e/e2e_test.go index f44c062a..c02f161e 100644 --- a/e2e/e2e_test.go +++ b/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) } diff --git a/e2e/iframe_test.go b/e2e/iframe_test.go index ff3dada0..a162aafe 100644 --- a/e2e/iframe_test.go +++ b/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") }) }