From 2da188fa0cdc42da057808978cd747df7a1f1198 Mon Sep 17 00:00:00 2001 From: Kornilios Kourtis Date: Tue, 9 Jan 2024 08:34:39 +0100 Subject: [PATCH] tetragon-vmtests-run: support for detailed results MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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 --- cmd/tetragon-vmtests-run/conf.go | 2 + cmd/tetragon-vmtests-run/main.go | 9 +- cmd/tetragon-vmtests-run/run_tests.go | 163 +++++++++++++++++++++++--- 3 files changed, 155 insertions(+), 19 deletions(-) diff --git a/cmd/tetragon-vmtests-run/conf.go b/cmd/tetragon-vmtests-run/conf.go index 97f514ed7c4..482dcadeeb7 100644 --- a/cmd/tetragon-vmtests-run/conf.go +++ b/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 } diff --git a/cmd/tetragon-vmtests-run/main.go b/cmd/tetragon-vmtests-run/main.go index a5135ede6bc..fa2f904d0a8 100644 --- a/cmd/tetragon-vmtests-run/main.go +++ b/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 /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) diff --git a/cmd/tetragon-vmtests-run/run_tests.go b/cmd/tetragon-vmtests-run/run_tests.go index 601809d3ce3..2e190fb4bbf 100644 --- a/cmd/tetragon-vmtests-run/run_tests.go +++ b/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) + } + } + } + }