tetragon-vmtests-run: support for detailed results

There are two ways to skip a test in our CI:
 1. add it to CiBlacklist in split-tetragon-gotests
 2. use t.Skip()

CI results report 1., but they do not report 2.

This means that skipped tests can go easily unnoticed.

To report tests skipped with (2), we need to parse the result files.
This patch does exactly that. It adds a new option
--enable-detailed-results. If this option is set, we set KeepAllLogs
because we need to parse all logs after the tests are finished.

The tests we skip with (1) are marked with ⏭️.
We introduce a new symbol for the tests that are skipped with (2): ⚡

Parsing the detailed results allows us to also report sub-tests (i.e.,
tests executed with t.Run()).

Here's an output example:

```
✅      pkg.sensors.tracing.Test_Kprobe_DisableEnablePolicy                                     (total:3 failed:0 skipped:0)    2.680496982s    1m33.952671893s
├─✅    Test_Kprobe_DisableEnablePolicy/sensor                                                  1.05s                           (1.05s)
├─✅    Test_Kprobe_DisableEnablePolicy/tracing-policy                                          1.09s                           (2.14s)
└─✅    Test_Kprobe_DisableEnablePolicy                                                         2.56s                           (4.7s)
⚡      pkg.sensors.tracing.TestKillerOverride32                                                (total:1 failed:0 skipped:1)    130.759191ms    1m34.083431084s
⚡      pkg.sensors.tracing.TestKillerSignal32                                                  (total:1 failed:0 skipped:1)    132.393451ms    1m34.215824535s
⚡      pkg.sensors.tracing.TestKillerOverrideBothBits                                          (total:1 failed:0 skipped:1)    119.455061ms    1m34.335279596s
⚡      pkg.sensors.tracing.TestKillerOverride                                                  (total:1 failed:0 skipped:1)    121.255148ms    1m34.456534744s
⚡      pkg.sensors.tracing.TestKillerSignal                                                    (total:1 failed:0 skipped:1)    136.665421ms    1m34.593200165s
✅      pkg.sensors.tracing.TestKillerMulti                                                     (total:1 failed:0 skipped:0)    132.761861ms    1m34.725962026s
```

Signed-off-by: Kornilios Kourtis <kornilios@isovalent.com>

cmd/tetragon-vmtests-run/conf.go

@@ -27,6 +27,8 @@ type RunConf struct {
 	disableUnifiedCgroups bool
 	portForwards          runner.PortForwards
 	testerConf            vmtests.Conf
+	detailedResults       bool
+	keepAllLogs           bool
 
 	filesystems []QemuFS
 }

cmd/tetragon-vmtests-run/main.go

@@ -35,6 +35,12 @@ func main() {
 				return fmt.Errorf("error parseing ports: %w", err)
 			}
 
+			// Keep all logs if user asked for it, or if user asked for detailed results
+			// since we need the log files to generate them.
+			if rcnf.keepAllLogs || rcnf.detailedResults {
+				rcnf.testerConf.KeepAllLogs = true
+			}
+
 			// Hardcoded (for now):
 			// mount cwd as cwd in the VM (this helps with contrib/test-progs paths)
 			// set output to be <cwd>/tester-tetragon.out.
@@ -150,10 +156,11 @@ func main() {
 	cmd.Flags().StringVar(&rcnf.testerConf.TestsFile, "testsfile", "", "list of tests to run")
 	cmd.Flags().StringVar(&rcnf.btfFile, "btf-file", "", "BTF file to use.")
 	cmd.Flags().BoolVar(&rcnf.testerConf.FailFast, "fail-fast", false, "Exit as soon as an error is encountered.")
-	cmd.Flags().BoolVar(&rcnf.testerConf.KeepAllLogs, "keep-all-logs", false, "Normally, logs are kept only for failed tests. This switch keeps all logs.")
+	cmd.Flags().BoolVar(&rcnf.keepAllLogs, "keep-all-logs", false, "Normally, logs are kept only for failed tests. This switch keeps all logs.")
 	cmd.Flags().BoolVar(&rcnf.disableUnifiedCgroups, "disable-unified-cgroups", false, "boot with systemd.unified_cgroup_hierarchy=0.")
 	cmd.Flags().StringArrayVarP(&ports, "port", "p", nil, "Forward a port (hostport[:vmport[:tcp|udp]])")
 	cmd.Flags().StringVar(&rcnf.testerConf.KernelVer, "kernel-ver", "", "kenel version")
+	cmd.Flags().BoolVar(&rcnf.detailedResults, "enable-detailed-results", false, "produce detailed results")
 
 	if err := cmd.Execute(); err != nil {
 		os.Exit(1)

cmd/tetragon-vmtests-run/run_tests.go

@@ -5,6 +5,7 @@ package main
 
 import (
 	"bufio"
+	"bytes"
 	"context"
 	"encoding/json"
 	"fmt"
@@ -22,6 +23,7 @@ import (
 
 type runTestsResults struct {
 	nrTests, nrFailedTests, nrSkipedTests int
+	totalDuration                         time.Duration
 }
 
 func runTests(
@@ -66,28 +68,153 @@ func runTests(
 		results = append(results, result)
 	}
 
-	var totalDuration time.Duration
-	errCnt := 0
-	skipCnt := 0
+	var out runTestsResults
 	w := new(tabwriter.Writer)
 	w.Init(os.Stdout, 0, 8, 0, '\t', 0)
-	for _, r := range results {
-		totalDuration += r.Duration
-		ok := "✅"
-		if r.Error {
-			ok = "❌"
-			errCnt++
-		} else if r.Skip {
-			ok = "⏭️"
-			skipCnt++
+	for _, res := range results {
+		// NB: res.Skip means that the test was never executed, so we cannot print detailed
+		// results.
+		if rcnf.detailedResults && res.Outfile != "" && !res.Skip {
+			updateResultsDetailed(w, &res, &out)
+		} else {
+			updateResultsSimple(w, &res, &out)
 		}
-		fmt.Fprintf(w, "%s\t%s\t%s\t(%s)\n", ok, r.Name, r.Duration.Round(time.Millisecond), totalDuration.Round(time.Millisecond))
 	}
 	w.Flush()
 
-	return &runTestsResults{
-		nrTests:       len(results),
-		nrFailedTests: errCnt,
-		nrSkipedTests: skipCnt,
-	}, nil
+	return &out, nil
+}
+
+func updateResultsSimple(w io.Writer, res *vmtests.Result, out *runTestsResults) {
+	out.nrTests++
+	out.totalDuration += res.Duration
+	ok := "✅"
+	if res.Error {
+		ok = "❌"
+		out.nrFailedTests++
+	} else if res.Skip {
+		// "⏭️"
+		// ok = "\u23E9"
+		out.nrSkipedTests++
+	}
+	fmt.Fprintf(w, "%s\t%s\t%s\t(%s)\n", ok, res.Name, res.Duration.Round(time.Millisecond), out.totalDuration.Round(time.Millisecond))
+}
+
+// see: https://pkg.go.dev/cmd/test2json
+type TestEvent struct {
+	Time    time.Time // encodes as an RFC3339-format string
+	Action  string
+	Package string
+	Test    string
+	Elapsed float64 // seconds
+	Output  string
+}
+
+func updateResultsDetailed(w io.Writer, res *vmtests.Result, out *runTestsResults) {
+
+	ctx, cancel := context.WithTimeout(context.Background(), 10*time.Second)
+	defer cancel()
+
+	f, err := os.Open(res.Outfile)
+	if err != nil {
+		fmt.Fprintf(os.Stderr, "Error openning %s: %v", res.Outfile, res)
+		updateResultsSimple(w, res, out)
+		return
+	}
+	defer f.Close()
+
+	prog := "go"
+	// NB: we need -t to enable timestamps and get the Elapsed field
+	args := []string{"tool", "test2json", "-t"}
+	cmd := exec.CommandContext(ctx, prog, args...)
+	cmd.Stdin = f
+	output, err := cmd.CombinedOutput()
+	if err != nil {
+		fmt.Fprintf(os.Stderr, "Error executing test2json: %v", res)
+		updateResultsSimple(w, res, out)
+		return
+	}
+	buff := bytes.NewBuffer(output)
+	scanner := bufio.NewScanner(buff)
+
+	var totalDuration time.Duration
+
+	type detail struct {
+		name string
+		icon string
+		dur  time.Duration
+	}
+	var details []detail
+
+	nrTests := 0
+	nrSkippedTests := 0
+	nrFailedTests := 0
+	for scanner.Scan() {
+		var tevent TestEvent
+		line := scanner.Bytes()
+		err := json.Unmarshal(line, &tevent)
+		if err != nil {
+			fmt.Fprintf(os.Stderr, "Error parsing: '%s': %v, bailing out", line, err)
+			updateResultsSimple(w, res, out)
+			return
+		}
+		if tevent.Test == "" {
+			continue
+		}
+
+		var icon string
+		switch tevent.Action {
+		case "skip":
+			nrSkippedTests++
+			// "⚡"
+			icon = "\u26a1"
+		case "pass":
+			icon = "✅"
+		case "fail":
+			nrFailedTests++
+			icon = "❌"
+		default:
+			continue
+		}
+
+		nrTests++
+		dur := time.Duration(float64(time.Second) * tevent.Elapsed)
+		details = append(details, detail{name: tevent.Test, icon: icon, dur: dur})
+
+	}
+
+	if err := scanner.Err(); err != nil {
+		fmt.Fprintf(os.Stderr, "Scanner failed: %v, bailing out", err)
+		updateResultsSimple(w, res, out)
+		return
+	}
+
+	out.totalDuration += res.Duration
+	out.nrTests += nrTests
+	out.nrSkipedTests += nrSkippedTests
+	out.nrFailedTests += nrFailedTests
+
+	icon := "✅"
+	if res.Error {
+		icon = "❌"
+	} else if nrSkippedTests == nrTests {
+		// "⚡"
+		icon = "\u26a1"
+	} else if nrFailedTests > 0 {
+		// NB(kkourt): res.Error should not be false
+		icon = "⁉️"
+	}
+
+	fmt.Fprintf(w, "%s\t%s\t(total:%d failed:%d skipped:%d)\t%s\t%s\n", icon, res.Name, nrTests, nrFailedTests, nrSkippedTests, res.Duration, out.totalDuration)
+	if len(details) > 1 {
+		for i, detail := range details {
+			totalDuration += detail.dur
+			if i == len(details)-1 {
+				fmt.Fprintf(w, "└─%s\t%s\t%s\t(%s)\n", detail.icon, detail.name, detail.dur.Round(time.Millisecond), totalDuration)
+			} else {
+				fmt.Fprintf(w, "├─%s\t%s\t%s\t(%s)\n", detail.icon, detail.name, detail.dur.Round(time.Millisecond), totalDuration)
+			}
+		}
+	}
+
 }