tests: Fix test flake from timestamp sanitization (#2713)

* Fix test flake from timestamp sanitization

When timestamps "overlap", sanitization did not work correctly.

For example:

in 1s ... in 2.1s

The first substitution would replace 1s => 0s

in 0s ... in 2.0s

The second substitution is predetermined, and replaces 2.1s => 0s, but
2.1s is no longer in the string.

* Use new sanitization function in tests, remove old function

Author: justinsb

go.mod

@@ -5,6 +5,7 @@ go 1.16
 require (
 	github.com/cpuguy83/go-md2man/v2 v2.0.0
 	github.com/go-errors/errors v1.4.0
+	github.com/google/go-cmp v0.5.6
 	github.com/google/shlex v0.0.0-20191202100458-e7afc7fbc510
 	github.com/igorsobreira/titlecase v0.0.0-20140109233139-4156b5b858ac
 	github.com/otiai10/copy v1.6.0

pkg/test/runner/runner.go

@@ -20,9 +20,10 @@ import (
 	"os"
 	"os/exec"
 	"path/filepath"
-	"regexp"
 	"strings"
 	"testing"
+
+	"github.com/google/go-cmp/cmp"
 )
 
 // Runner runs an e2e test
@@ -247,16 +248,22 @@ func (r *Runner) runFnEval() error {
 	return nil
 }
 
-// Match strings starting with [PASS] or [FAIL] and ending with " in N...". We capture the duration portion
-var timestampRegex = regexp.MustCompile(`\[(?:PASS|FAIL)].* in ([0-9].*)`)
-
 func sanitizeTimestamps(stderr string) string {
 	// Output will have non-deterministic output timestamps. We will replace these to static message for
 	// stable comparison in tests.
-	for _, m := range timestampRegex.FindAllStringSubmatch(stderr, -1) {
-		stderr = strings.ReplaceAll(stderr, m[1], "0s")
+	var sanitized []string
+	for _, line := range strings.Split(stderr, "\n") {
+		// [PASS] \"gcr.io/kpt-fn/set-namespace:v0.1.3\" in 2.0s
+		if strings.HasPrefix(line, "[PASS]") || strings.HasPrefix(line, "[FAIL]") {
+			tokens := strings.Fields(line)
+			if len(tokens) == 4 && tokens[2] == "in" {
+				tokens[3] = "0s"
+				line = strings.Join(tokens, " ")
+			}
+		}
+		sanitized = append(sanitized, line)
 	}
-	return stderr
+	return strings.Join(sanitized, "\n")
 }
 
 // IsFnResultExpected determines if function results are expected for this testcase.
@@ -467,10 +474,12 @@ func (r *Runner) compareResult(cnt int, exitErr error, stdout string, stderr str
 func (r *Runner) compareOutput(stdout string, stderr string) error {
 	expectedStderr := r.testCase.Config.StdErr
 	if !strings.Contains(stderr, expectedStderr) {
+		r.t.Logf("stderr diff is %s", cmp.Diff(expectedStderr, stderr))
 		return fmt.Errorf("wanted stderr %q, got %q", expectedStderr, stderr)
 	}
 	expectedStdout := r.testCase.Config.StdOut
 	if !strings.Contains(stdout, expectedStdout) {
+		r.t.Logf("stdout diff is %s", cmp.Diff(expectedStdout, stdout))
 		return fmt.Errorf("wanted stdout %q, got %q", expectedStdout, stdout)
 	}
 	return nil

pkg/test/runner/sanitize_test.go

@@ -0,0 +1,73 @@
+package runner
+
+import (
+	"testing"
+
+	"github.com/google/go-cmp/cmp"
+)
+
+func TestSanitizeTimestamps(t *testing.T) {
+	grid := []struct {
+		Name   string
+		Input  string
+		Output string
+	}{
+		{
+			Name: "Prefix match: 12s and 12.1s",
+			Input: `
+[RUNNING] \"gcr.io/kpt-fn/starlark:v0.2.1\"
+[PASS] \"gcr.io/kpt-fn/starlark:v0.2.1\" in 12s
+[RUNNING] \"gcr.io/kpt-fn/set-namespace:v0.1.3\" on 1 resource(s)
+[PASS] \"gcr.io/kpt-fn/set-namespace:v0.1.3\" in 12.1s
+`,
+			Output: `
+[RUNNING] \"gcr.io/kpt-fn/starlark:v0.2.1\"
+[PASS] \"gcr.io/kpt-fn/starlark:v0.2.1\" in 0s
+[RUNNING] \"gcr.io/kpt-fn/set-namespace:v0.1.3\" on 1 resource(s)
+[PASS] \"gcr.io/kpt-fn/set-namespace:v0.1.3\" in 0s
+`,
+		},
+		{
+			Name: "Suffix match: 1s and 0.1s",
+			Input: `
+[RUNNING] \"gcr.io/kpt-fn/starlark:v0.2.1\"
+[PASS] \"gcr.io/kpt-fn/starlark:v0.2.1\" in 1s
+[RUNNING] \"gcr.io/kpt-fn/set-namespace:v0.1.3\" on 1 resource(s)
+[PASS] \"gcr.io/kpt-fn/set-namespace:v0.1.3\" in 0.1s
+`,
+			Output: `
+[RUNNING] \"gcr.io/kpt-fn/starlark:v0.2.1\"
+[PASS] \"gcr.io/kpt-fn/starlark:v0.2.1\" in 0s
+[RUNNING] \"gcr.io/kpt-fn/set-namespace:v0.1.3\" on 1 resource(s)
+[PASS] \"gcr.io/kpt-fn/set-namespace:v0.1.3\" in 0s
+`,
+		},
+		{
+			Name: "Only substitute matching lines",
+			Input: `
+[RUNNING] \"gcr.io/kpt-fn/starlark:v0.2.1\"
+[PASS] \"gcr.io/kpt-fn/starlark:v0.2.1\" in 1s
+[RUNNING] \"gcr.io/kpt-fn/set-namespace:1s\" on 1 resource(s)
+[PASS] \"gcr.io/kpt-fn/set-namespace:v0.1.3\" notin 1s
+`,
+			Output: `
+[RUNNING] \"gcr.io/kpt-fn/starlark:v0.2.1\"
+[PASS] \"gcr.io/kpt-fn/starlark:v0.2.1\" in 0s
+[RUNNING] \"gcr.io/kpt-fn/set-namespace:1s\" on 1 resource(s)
+[PASS] \"gcr.io/kpt-fn/set-namespace:v0.1.3\" notin 1s
+`,
+		},
+	}
+
+	for _, g := range grid {
+		g := g // Avoid range go-tcha
+		t.Run(g.Name, func(t *testing.T) {
+			got := sanitizeTimestamps(g.Input)
+			want := g.Output
+
+			if diff := cmp.Diff(got, want); diff != "" {
+				t.Errorf("unexpected results (-want, +got): %s", diff)
+			}
+		})
+	}
+}