roachtest: detect sysbench crashes when preparing workload

Sysbench is known to flake with crashes. Previously, we would detect
these crashes when running the workload and pass the run to avoid noise.

This change now does the same when preparing the workload as well. It also
skips the test instead of passing the test. This makes it easier to identify
tests that actually ran to completion and has consequences for test selection.

We also add a small helper to prefix out sysbench output with timestamps, this
should aid debugging.

Author: DarrylWong

pkg/cmd/roachtest/roachtestutil/utils.go

@@ -279,3 +279,12 @@ func PortLatency(
 	}
 	return time.Duration(avgRTT * float64(time.Second)), nil
 }
+
+// PrefixCmdOutputWithTimestamp wraps a remote command such that it pipes
+// stdout and stderr through awk and prepends the timestamp. Can be used to aid
+// debugging long-running commands that don't already prefix output with timestamps.
+func PrefixCmdOutputWithTimestamp(cmd string) string {
+	// Don't prefix blank lines with timestamps.
+	awkCmd := `awk 'NF { cmd="date +\"%H:%M:%S\""; cmd | getline ts; close(cmd); print ts ":", $0; next } { print }'`
+	return fmt.Sprintf(`bash -c '%s' 2>&1 |`, cmd) + awkCmd
+}

pkg/cmd/roachtest/tests/sysbench.go

@@ -195,9 +195,11 @@ func runSysbench(ctx context.Context, t test.Test, c cluster.Cluster, opts sysbe
 		t.Status("preparing workload")
 		cmd := opts.cmd(useHAProxy /* haproxy */)
 		{
-			result, err := c.RunWithDetailsSingleNode(ctx, t.L(), option.WithNodes(c.WorkloadNode()), cmd+" prepare")
+			result, err := c.RunWithDetailsSingleNode(ctx, t.L(), option.WithNodes(c.WorkloadNode()), roachtestutil.PrefixCmdOutputWithTimestamp(cmd+" prepare"))
 			if err != nil {
 				return err
+			} else if msg, crashed := detectSysbenchCrash(result); crashed {
+				t.Skipf("%s; skipping test", msg)
 			} else if strings.Contains(result.Stdout, "FATAL") {
 				// sysbench prepare doesn't exit on errors for some reason, so we have
 				// to check that it didn't silently fail. We've seen it do so, causing
@@ -225,11 +227,10 @@ func runSysbench(ctx context.Context, t test.Test, c cluster.Cluster, opts sysbe
 
 		t.Status("running workload")
 		start = timeutil.Now()
-		result, err := c.RunWithDetailsSingleNode(ctx, t.L(), option.WithNodes(c.WorkloadNode()), cmd+" run")
+		result, err := c.RunWithDetailsSingleNode(ctx, t.L(), option.WithNodes(c.WorkloadNode()), roachtestutil.PrefixCmdOutputWithTimestamp(cmd+" run"))
 
 		if msg, crashed := detectSysbenchCrash(result); crashed {
-			t.L().Printf("%s; passing test anyway", msg)
-			return nil
+			t.Skipf("%s; skipping test", msg)
 		}
 
 		if err != nil {