~eliasnaur/gio-patches

cmd/gogio: introduce retries with backoff to the e2e tests v1 PROPOSED

Daniel Martí: 1
 cmd/gogio: introduce retries with backoff to the e2e tests

 3 files changed, 134 insertions(+), 64 deletions(-)
Export patchset (mbox)
How do I use this?

Copy & paste the following snippet into your terminal to import this patchset into git:

curl -s https://lists.sr.ht/~eliasnaur/gio-patches/patches/9758/mbox | git am -3
Learn more about email & git

[PATCH] cmd/gogio: introduce retries with backoff to the e2e tests Export this patch

Right now, this was badly needed for the wayland subtest, as it seems
like waiting for a frame to be ready wasn't enough for the screenshot to
show what we want. In practice, even if the machine was idle, it could
sometimes take a few extra milliseconds for the app to first appear on
the display.

This was worse when the machine is under stress, which is often the case
with CI. For example, the command below showed a ~20% failure rate on my
laptop with four cores:

	go test -c -o test && stress ./test -test.run EndToEnd/Wayland

Add a generic withRetries helper function, which allows us to keep
trying some action up to a timeout, with sleeps in between that start at
100ms and keep doubling until 2s. The function also logs before each
sleep, in case the user is confused why their test is stuck for
potentially may seconds at once.

Refactor the wantColors function into a separate function that returns
an error, as we can no longer directly report errors via *testing.T. It
still reports all the mismatches at once, which is useful. It can now be
used on to pof withRetries with a thin wrapper.

While at it, make the X11 subtest use withRetries to wait for the X
server to be ready. It was using a simpler method with a fixed number of
static sleeps. It's now more consistent, and a bit better overall.

With the changes above, the 'stress' command from earlier can get past
100 runs on my laptop with no failures at all.

Finally, fix a rogue log.Fatal call I had somehow missed.

Signed-off-by: Daniel Martí <mvdan@mvdan.cc>
---
 cmd/gogio/e2e_test.go     | 177 +++++++++++++++++++++++++++-----------
 cmd/gogio/wayland_test.go |   3 +-
 cmd/gogio/x11_test.go     |  18 ++--
 3 files changed, 134 insertions(+), 64 deletions(-)

diff --git a/cmd/gogio/e2e_test.go b/cmd/gogio/e2e_test.go
index 5d29617..c6f5f06 100644
--- a/cmd/gogio/e2e_test.go
+++ b/cmd/gogio/e2e_test.go
@@ -3,9 +3,12 @@
package main_test

import (
	"errors"
	"flag"
	"fmt"
	"image"
	"image/color"
	"strings"
	"testing"
	"time"
)
@@ -84,47 +87,6 @@ func runEndToEndTest(t *testing.T, driver TestDriver) {
	t.Log("starting driver and gio app")
	driver.Start("testdata/red.go", size.X, size.Y)

	// The colors are split in four rectangular sections. Check the corners
	// of each of the sections. We check the corners left to right, top to
	// bottom, like when reading left-to-right text.
	wantColors := func(topLeft, topRight, botLeft, botRight color.RGBA) {
		t.Helper()
		img := driver.Screenshot()
		size = img.Bounds().Size()
		{
			minX, minY := 5, 5
			maxX, maxY := (size.X/2)-5, (size.Y/2)-5
			wantColor(t, img, minX, minY, topLeft)
			wantColor(t, img, maxX, minY, topLeft)
			wantColor(t, img, minX, maxY, topLeft)
			wantColor(t, img, maxX, maxY, topLeft)
		}
		{
			minX, minY := (size.X/2)+5, 5
			maxX, maxY := size.X-5, (size.Y/2)-5
			wantColor(t, img, minX, minY, topRight)
			wantColor(t, img, maxX, minY, topRight)
			wantColor(t, img, minX, maxY, topRight)
			wantColor(t, img, maxX, maxY, topRight)
		}
		{
			minX, minY := 5, (size.Y/2)+5
			maxX, maxY := (size.X/2)-5, size.Y-5
			wantColor(t, img, minX, minY, botLeft)
			wantColor(t, img, maxX, minY, botLeft)
			wantColor(t, img, minX, maxY, botLeft)
			wantColor(t, img, maxX, maxY, botLeft)
		}
		{
			minX, minY := (size.X/2)+5, (size.Y/2)+5
			maxX, maxY := size.X-5, size.Y-5
			wantColor(t, img, minX, minY, botRight)
			wantColor(t, img, maxX, minY, botRight)
			wantColor(t, img, minX, maxY, botRight)
			wantColor(t, img, maxX, maxY, botRight)
		}
	}

	beef := color.RGBA{R: 0xde, G: 0xad, B: 0xbe}
	white := color.RGBA{R: 0xff, G: 0xff, B: 0xff}
	black := color.RGBA{R: 0x00, G: 0x00, B: 0x00}
@@ -133,7 +95,11 @@ func runEndToEndTest(t *testing.T, driver TestDriver) {

	// These are the four colors at the beginning.
	t.Log("taking initial screenshot")
	wantColors(beef, white, black, gray)
	withRetries(t, 2*time.Second, func() error {
		img := driver.Screenshot()
		size = img.Bounds().Size() // override the default size
		return checkImageCorners(img, beef, white, black, gray)
	})

	// TODO(mvdan): implement this properly in the Wayland driver; swaymsg
	// almost works to automate clicks, but the button presses end up in the
@@ -146,18 +112,129 @@ func runEndToEndTest(t *testing.T, driver TestDriver) {
	t.Log("clicking twice and taking another screenshot")
	driver.Click(1*(size.X/4), 1*(size.Y/4))
	driver.Click(3*(size.X/4), 3*(size.Y/4))
	wantColors(red, white, black, red)
	withRetries(t, 2*time.Second, func() error {
		img := driver.Screenshot()
		return checkImageCorners(img, red, white, black, red)
	})
}

func wantColor(t *testing.T, img image.Image, x, y int, want color.Color) {
// withRetries keeps retrying fn until it succeeds, or until the timeout is hit.
// It uses a rudimentary kind of backoff, which starts with 100ms delays. As
// such, timeout should generally be in the order of seconds.
func withRetries(t *testing.T, timeout time.Duration, fn func() error) {
	t.Helper()
	r, g, b, _ := want.RGBA()
	got := img.At(x, y)
	r_, g_, b_, _ := got.RGBA()
	if r_ != r || g_ != g || b_ != b {
		t.Errorf("got 0x%04x%04x%04x at (%d,%d), want 0x%04x%04x%04x",
			r_, g_, b_, x, y, r, g, b)

	timeoutTimer := time.NewTimer(timeout)
	defer timeoutTimer.Stop()
	backoff := 100 * time.Millisecond

	tries := 0
	var lastErr error
	for {
		if lastErr = fn(); lastErr == nil {
			return
		}
		tries++
		t.Logf("retrying after %s", backoff)

		// Use a timer instead of a sleep, so that the timeout can stop
		// the backoff early. Don't reuse this timer, since we're not in
		// a hot loop, and we don't want tricky code.
		backoffTimer := time.NewTimer(backoff)
		defer backoffTimer.Stop()

		select {
		case <-timeoutTimer.C:
			t.Errorf("last error: %v", lastErr)
			t.Fatalf("hit timeout of %s after %d tries", timeout, tries)
		case <-backoffTimer.C:
		}

		// Keep doubling it until a maximum. With the start at 100ms,
		// we'll do: 100ms, 200ms, 400ms, 800ms, 1.6s, and 2s forever.
		backoff *= 2
		if max := 2 * time.Second; backoff > max {
			backoff = max
		}
	}
}

type colorMismatch struct {
	x, y            int
	wantRGB, gotRGB [3]uint32
}

func (m colorMismatch) String() string {
	return fmt.Sprintf("%3d,%-3d got 0x%04x%04x%04x, want 0x%04x%04x%04x",
		m.x, m.y,
		m.gotRGB[0], m.gotRGB[1], m.gotRGB[2],
		m.wantRGB[0], m.wantRGB[1], m.wantRGB[2],
	)
}

func checkImageCorners(img image.Image, topLeft, topRight, botLeft, botRight color.RGBA) error {
	// The colors are split in four rectangular sections. Check the corners
	// of each of the sections. We check the corners left to right, top to
	// bottom, like when reading left-to-right text.

	size := img.Bounds().Size()
	var mismatches []colorMismatch

	checkColor := func(x, y int, want color.Color) {
		r, g, b, _ := want.RGBA()
		got := img.At(x, y)
		r_, g_, b_, _ := got.RGBA()
		if r_ != r || g_ != g || b_ != b {
			mismatches = append(mismatches, colorMismatch{
				x:       x,
				y:       y,
				wantRGB: [3]uint32{r, g, b},
				gotRGB:  [3]uint32{r_, g_, b_},
			})
		}
	}

	{
		minX, minY := 5, 5
		maxX, maxY := (size.X/2)-5, (size.Y/2)-5
		checkColor(minX, minY, topLeft)
		checkColor(maxX, minY, topLeft)
		checkColor(minX, maxY, topLeft)
		checkColor(maxX, maxY, topLeft)
	}
	{
		minX, minY := (size.X/2)+5, 5
		maxX, maxY := size.X-5, (size.Y/2)-5
		checkColor(minX, minY, topRight)
		checkColor(maxX, minY, topRight)
		checkColor(minX, maxY, topRight)
		checkColor(maxX, maxY, topRight)
	}
	{
		minX, minY := 5, (size.Y/2)+5
		maxX, maxY := (size.X/2)-5, size.Y-5
		checkColor(minX, minY, botLeft)
		checkColor(maxX, minY, botLeft)
		checkColor(minX, maxY, botLeft)
		checkColor(maxX, maxY, botLeft)
	}
	{
		minX, minY := (size.X/2)+5, (size.Y/2)+5
		maxX, maxY := size.X-5, size.Y-5
		checkColor(minX, minY, botRight)
		checkColor(maxX, minY, botRight)
		checkColor(minX, maxY, botRight)
		checkColor(maxX, maxY, botRight)
	}
	if n := len(mismatches); n > 0 {
		b := new(strings.Builder)
		fmt.Fprintf(b, "encountered %d color mismatches:\n", n)
		for _, m := range mismatches {
			fmt.Fprintf(b, "%s\n", m)
		}
		return errors.New(b.String())
	}
	return nil
}

func (d *driverBase) waitForFrame() {
diff --git a/cmd/gogio/wayland_test.go b/cmd/gogio/wayland_test.go
index d10ea82..8288a67 100644
--- a/cmd/gogio/wayland_test.go
+++ b/cmd/gogio/wayland_test.go
@@ -11,7 +11,6 @@ import (
	"image/png"
	"io"
	"io/ioutil"
	"log"
	"os"
	"os/exec"
	"path/filepath"
@@ -103,7 +102,7 @@ func (d *WaylandTestDriver) Start(path string, width, height int) {
		cmd.Env = env
		stderr, err := cmd.StderrPipe()
		if err != nil {
			log.Fatal(err)
			d.Fatal(err)
		}
		if err := cmd.Start(); err != nil {
			d.Fatal(err)
diff --git a/cmd/gogio/x11_test.go b/cmd/gogio/x11_test.go
index 5774e09..4dd9fa7 100644
--- a/cmd/gogio/x11_test.go
+++ b/cmd/gogio/x11_test.go
@@ -95,19 +95,13 @@ func (d *X11TestDriver) Start(path string, width, height int) {
			time.Sleep(10 * time.Millisecond)
		})

		// Wait for up to 1s (100 * 10ms) for the X server to be ready.
		for i := 0; ; i++ {
			time.Sleep(10 * time.Millisecond)
			// This socket path isn't terribly portable, but it's
			// okay for now.
		// Wait for the X server to be ready. The socket path isn't
		// terribly portable, but that's okay for now.
		withRetries(d.T, time.Second, func() error {
			socket := fmt.Sprintf("/tmp/.X11-unix/X%s", d.display[1:])
			if _, err := os.Stat(socket); err == nil {
				break
			}
			if i >= 100 {
				d.Fatalf("timed out waiting for %s", socket)
			}
		}
			_, err := os.Stat(socket)
			return err
		})

		wg.Add(1)
		go func() {
-- 
2.25.0
Thanks, applied.
View this thread in the archives