Repository: kudobuilder/kuttl
Pull request #509 (2024-03-14 10:30:57)

Increase granularity of JUnit reports.
# What

Change the report schema.

Previously:
```
<testsuites> (everything)
  <testsuite> (directory of tests)
   <testcase> (a test directory containing steps)
```

Now:

```
<testsuites> (everything)
  <testsuite> (directory of tests)
   <testsuite> (a test directory containing steps)
     <testcase> (a single step)
```

See example at the bottom.

# Why

## Improved automation

The primary driver for this change is increasing quality of bug reports that are filed by automation based on the JUnit report files by [junit2jira](https://github.com/stackrox/junit2jira).

The tests in the stackrox suite are rather heavyweight, because the operands under test are heavyweight - resource-hungry and slow to set up. This means each test consists of a rather long series of steps - each making assertions after flipping a certain feature on or off. 

However this means that each test can fail for a variety of mostly unrelated reasons.

One important thing to understand is how `junit2jira` coalesces reports. It treats the concatenation of `<testcase>`'s `classname` and `name` attributes as the key (title) for tickets. Once its detects a ticket with the same title already exists, then it appends a comment to this existing ticket, rather than create a new one.

However given the above, this leads to ever-growing tickets with just vaguely related failure root causes (after a while).

Changing the report to map each `<testcase>` to a kuttl step, rather than whole test, is going to make these automated reports more meaningful and easier to deal with.

## More detailed time data

An additional advantage is the more granular timing data - shows which steps are the slow ones.

# Caveats

While it seems that nested `<testsuite>` elements are widely accepted as valid ([[1](https://github.com/testmoapp/junitxml?tab=readme-ov-file#basic-junit-xml-structure)], [[2](https://github.com/joshdk/go-junit/blob/1879d36af29d409dec16c57250f859ee06df9a7a/ingest.go#L27-L37)] not all JUnit parsing tools might support this out of the box, so there is some potential for breaking existing workflows.

FWIW, so far there were no [comments on slack](https://kubernetes.slack.com/archives/CG3HTFCMV/p1710759627410109) about this change, so perhaps there are not many report users.

If needed, I could add a knob to make this high-granularity opt-in.

# Example

Before:
```
<testsuites name="" tests="4" failures="0" time="843.243">
  <testsuite tests="2" failures="0" timestamp="2024-03-06T13:03:26.798769149Z" time="829.547" name="./tests/central">
    <testcase classname="central" name="central-misc" timestamp="2024-03-06T13:03:26.844298978Z" time="708.114" assertions="142"/>
    <testcase classname="central" name="central-basic" timestamp="2024-03-06T13:03:26.833004446Z" time="829.513" assertions="117"/>
  </testsuite>
  <testsuite tests="1" failures="0" timestamp="2024-03-06T13:03:26.798868492Z" time="11.064" name="./tests/controller">
    <testcase classname="controller" name="metrics" timestamp="2024-03-06T13:03:26.808993539Z" time="11.054" assertions="4"/>
  </testsuite>
  <testsuite tests="1" failures="0" timestamp="2024-03-06T13:03:26.798915549Z" time="742.563" name="./tests/securedcluster">
    <testcase classname="securedcluster" name="sc-basic" timestamp="2024-03-06T13:03:26.832535251Z" time="742.529" assertions="120"/>
  </testsuite>
</testsuites>
```

After:
```
 <testsuites name="" tests="38" failures="3" time="1464.084">
   <testsuite tests="25" failures="1" timestamp="2024-03-14T10:27:42.483185024+01:00" time="1462.059" name="./tests/central">
     <testsuite tests="10" failures="1" timestamp="2024-03-14T10:27:42.494834755+01:00" time="1462.047" name="central-basic">
       <testcase classname="central-basic" name="setup" timestamp="2024-03-14T10:27:42.49483545+01:00" time="0.358" assertions="0"></testcase>
       <testcase classname="central-basic" name="step 0-image-pull-secrets" timestamp="2024-03-14T10:27:42.853144374+01:00" time="1.410" assertions="0"></testcase>
       <testcase classname="central-basic" name="step 10-central-cr" timestamp="2024-03-14T10:27:44.262843517+01:00" time="960.886" assertions="9"></testcase>
       <testcase classname="central-basic" name="step 11-" timestamp="2024-03-14T10:43:45.149194831+01:00" time="1.210" assertions="3"></testcase>
       <testcase classname="central-basic" name="step 20-verify-password" timestamp="2024-03-14T10:43:46.358720862+01:00" time="3.586" assertions="0"></testcase>
       <testcase classname="central-basic" name="step 30-change-password" timestamp="2024-03-14T10:43:49.944607399+01:00" time="0.663" assertions="0"></testcase>
       <testcase classname="central-basic" name="step 40-reconcile" timestamp="2024-03-14T10:43:50.607656485+01:00" time="84.499" assertions="2"></testcase>
       <testcase classname="central-basic" name="step 60-use-new-password" timestamp="2024-03-14T10:45:15.106773843+01:00" time="2.017" assertions="0"></testcase>
       <testcase classname="central-basic" name="step 75-switch-to-external-central-db" timestamp="2024-03-14T10:45:17.124277157+01:00" time="31.584" assertions="3"></testcase>
       <testcase classname="central-basic" name="step 76-switch-back-to-internal-central-db" timestamp="2024-03-14T10:45:48.707986107+01:00" time="375.834" assertions="8">
         <failure message="failed in step 76-switch-back-to-internal-central-db" type="">Get &#34;https://34.123.156.233/api/v1/namespaces/kuttl-test-immense-pipefish/pods?labelSelector=app%3Dcentral&#34;: dial tcp 34.123.156.233:443: i/o timeout</failure>
       </testcase>
     </testsuite>
     <testsuite tests="15" failures="0" timestamp="2024-03-14T10:27:42.499383151+01:00" time="582.342" name="central-misc">
       <testcase classname="central-misc" name="setup" timestamp="2024-03-14T10:27:42.499383924+01:00" time="0.334" assertions="0"></testcase>
       <testcase classname="central-misc" name="step 0-image-pull-secrets" timestamp="2024-03-14T10:27:42.833146338+01:00" time="1.421" assertions="0"></testcase>
       <testcase classname="central-misc" name="step 10-central-cr" timestamp="2024-03-14T10:27:44.254461703+01:00" time="274.741" assertions="9"></testcase>
       <testcase classname="central-misc" name="step 11-" timestamp="2024-03-14T10:32:18.99536279+01:00" time="0.001" assertions="0"></testcase>
       <testcase classname="central-misc" name="step 40-enable-declarative-config" timestamp="2024-03-14T10:32:18.996512371+01:00" time="52.885" assertions="7"></testcase>
       <testcase classname="central-misc" name="step 41-disable-declarative-config" timestamp="2024-03-14T10:33:11.881202981+01:00" time="24.417" assertions="7"></testcase>
       <testcase classname="central-misc" name="step 61-" timestamp="2024-03-14T10:33:36.298495291+01:00" time="27.786" assertions="6"></testcase>
       <testcase classname="central-misc" name="step 62-" timestamp="2024-03-14T10:34:04.084013669+01:00" time="0.001" assertions="0"></testcase>
       <testcase classname="central-misc" name="step 63-" timestamp="2024-03-14T10:34:04.084635668+01:00" time="3.991" assertions="10"></testcase>
       <testcase classname="central-misc" name="step 64-" timestamp="2024-03-14T10:34:08.075894938+01:00" time="0.001" assertions="0"></testcase>
       <testcase classname="central-misc" name="step 80-enable-telemetry" timestamp="2024-03-14T10:34:08.076476289+01:00" time="54.910" assertions="7"></testcase>
       <testcase classname="central-misc" name="step 81-disable-telemetry" timestamp="2024-03-14T10:35:02.986151412+01:00" time="61.031" assertions="7"></testcase>
       <testcase classname="central-misc" name="step 85-add-additional-ca" timestamp="2024-03-14T10:36:04.017433688+01:00" time="29.733" assertions="7"></testcase>
       <testcase classname="central-misc" name="step 900-delete-cr" timestamp="2024-03-14T10:36:33.750642603+01:00" time="47.214" assertions="72"></testcase>
       <testcase classname="central-misc" name="step 990-" timestamp="2024-03-14T10:37:20.964293466+01:00" time="3.878" assertions="10"></testcase>
     </testsuite>
   </testsuite>
   <testsuite tests="3" failures="1" timestamp="2024-03-14T10:27:42.483234892+01:00" time="19.295" name="./tests/controller">
     <testsuite tests="3" failures="1" timestamp="2024-03-14T10:27:42.48581535+01:00" time="19.292" name="metrics">
       <testcase classname="metrics" name="setup" timestamp="2024-03-14T10:27:42.485815837+01:00" time="0.367" assertions="0"></testcase>
       <testcase classname="metrics" name="step 100-rbac" timestamp="2024-03-14T10:27:42.853171423+01:00" time="2.741" assertions="0"></testcase>
       <testcase classname="metrics" name="step 200-access-no-auth" timestamp="2024-03-14T10:27:45.594328284+01:00" time="16.184" assertions="4">
         <failure message="failed in step 200-access-no-auth" type="">resource Pod:kuttl-test-intimate-monitor/operator-metrics-unprivileged: .status.phase: value mismatch, expected: Succeededx != actual: Succeeded</failure>
       </testcase>
     </testsuite>
   </testsuite>
   <testsuite tests="10" failures="1" timestamp="2024-03-14T10:27:42.483247762+01:00" time="1357.557" name="./tests/securedcluster">
     <testsuite tests="10" failures="1" timestamp="2024-03-14T10:27:42.496676933+01:00" time="1357.543" name="sc-basic">
       <testcase classname="sc-basic" name="setup" timestamp="2024-03-14T10:27:42.496677598+01:00" time="0.362" assertions="0"></testcase>
       <testcase classname="sc-basic" name="step 0-image-pull-secrets" timestamp="2024-03-14T10:27:42.858641218+01:00" time="1.405" assertions="0"></testcase>
       <testcase classname="sc-basic" name="step 5-central-cr" timestamp="2024-03-14T10:27:44.263432174+01:00" time="1059.093" assertions="6"></testcase>
       <testcase classname="sc-basic" name="step 7-fetch-bundle" timestamp="2024-03-14T10:45:23.356019926+01:00" time="5.870" assertions="3"></testcase>
       <testcase classname="sc-basic" name="step 10-secured-cluster-cr" timestamp="2024-03-14T10:45:29.226313899+01:00" time="55.764" assertions="5"></testcase>
       <testcase classname="sc-basic" name="step 12-" timestamp="2024-03-14T10:46:24.990194295+01:00" time="2.350" assertions="6"></testcase>
       <testcase classname="sc-basic" name="step 13-add-stackrox-secret" timestamp="2024-03-14T10:46:27.340006671+01:00" time="95.431" assertions="6"></testcase>
       <testcase classname="sc-basic" name="step 14-add-collector-secret" timestamp="2024-03-14T10:48:02.771277222+01:00" time="51.402" assertions="6"></testcase>
       <testcase classname="sc-basic" name="step 15-add-remaining-secrets" timestamp="2024-03-14T10:48:54.173424571+01:00" time="53.147" assertions="6"></testcase>
       <testcase classname="sc-basic" name="step 16-remove-dummy-secrets" timestamp="2024-03-14T10:49:47.320052808+01:00" time="32.720" assertions="6">
         <failure message="failed in step 16-remove-dummy-secrets" type="">retrieving API resource for /v1, Kind=Secret failed: Get &#34;https://34.123.156.233/api/v1?timeout=32s&#34;: net/http: request canceled (Client.Timeout exceeded while awaiting headers)</failure>
       </testcase>
     </testsuite>
   </testsuite>
 </testsuites>
```


Patch:
diff --git a/pkg/report/report.go b/pkg/report/report.go
index ef6d976..9d73441 100644
--- a/pkg/report/report.go
+++ b/pkg/report/report.go
@@ -6,6 +6,7 @@ import (
 	"fmt"
 	"os"
 	"path/filepath"
+	"sync"
 	"time"
 )
 
@@ -67,7 +68,7 @@ type Testcase struct {
 	end time.Time
 }
 
-// TestSuite is a collection of Testcase and is a summary of those details.
+// Testsuite is a collection of Testcase and is a summary of those details.
 type Testsuite struct {
 	// Tests is the number of Testcases in the collection.
 	Tests int `xml:"tests,attr" json:"tests"`
@@ -82,8 +83,11 @@ type Testsuite struct {
 	Name string `xml:"name,attr" json:"name"`
 	// Properties which are specific to this suite.
 	Properties *Properties `xml:"properties" json:"properties,omitempty"`
-	// Testcase is a collection of test cases.
-	Testcase []*Testcase `xml:"testcase" json:"testcase,omitempty"`
+	// Testcases is a collection of test cases.
+	Testcases []*Testcase `xml:"testcase" json:"testcase,omitempty"`
+	// SubSuites is a collection of child test suites.
+	SubSuites []*Testsuite `xml:"testsuite" json:"testsuite,omitempty"`
+	lock      sync.Mutex
 }
 
 // Testsuites is a collection of Testsuite and defines the rollup summary of all stats.
@@ -148,7 +152,7 @@ func (ts *Testsuite) AddTestcase(testcase *Testcase) {
 	testcase.Time = fmt.Sprintf("%.3f", elapsed.Seconds())
 	testcase.Classname = filepath.Base(ts.Name)
 
-	ts.Testcase = append(ts.Testcase, testcase)
+	ts.Testcases = append(ts.Testcases, testcase)
 	ts.Tests++
 	if testcase.Failure != nil {
 		ts.Failures++
@@ -168,6 +172,37 @@ func (ts *Testsuite) AddProperty(property Property) {
 	ts.Properties.Property = append(ts.Properties.Property, property)
 }
 
+// NewSubSuite creates a new child suite and returns it.
+func (ts *Testsuite) NewSubSuite(name string) *Testsuite {
+	s := NewSuite(name)
+	ts.lock.Lock()
+	defer ts.lock.Unlock()
+	ts.SubSuites = append(ts.SubSuites, s)
+	return s
+}
+
+// summarize sets counters and elapsed time attributes based on children.
+// Returns the timestamp of the end of latest child.
+func (ts *Testsuite) summarize() time.Time {
+	end := ts.Timestamp
+	for _, subSuite := range ts.SubSuites {
+		subSuiteEnd := subSuite.summarize()
+		if subSuiteEnd.After(end) {
+			end = subSuiteEnd
+		}
+		ts.Tests += subSuite.Tests
+		ts.Failures += subSuite.Failures
+	}
+	for _, testcase := range ts.Testcases {
+		if testcase.end.After(end) {
+			end = testcase.end
+		}
+	}
+	elapsed := end.Sub(ts.Timestamp)
+	ts.Time = fmt.Sprintf("%.3f", elapsed.Seconds())
+	return end
+}
+
 // AddTestSuite is a convenience method to add a testsuite to the collection in testsuites
 func (ts *Testsuites) AddTestSuite(testsuite *Testsuite) {
 	// testsuite is added prior to stat availability, stat management in the close of the testsuites
@@ -194,8 +229,7 @@ func (ts *Testsuites) Close() {
 
 	// async work makes this necessary (stats for each testsuite)
 	for _, testsuite := range ts.Testsuite {
-		elapsed = latestEnd(testsuite.Timestamp, testsuite.Testcase).Sub(testsuite.Timestamp)
-		testsuite.Time = fmt.Sprintf("%.3f", elapsed.Seconds())
+		testsuite.summarize()
 
 		ts.Tests += testsuite.Tests
 		ts.Failures += testsuite.Failures
@@ -203,15 +237,6 @@ func (ts *Testsuites) Close() {
 }
 
 // latestEnd provides the time of the latest end out of the collection of testcases
-func latestEnd(start time.Time, testcases []*Testcase) time.Time {
-	end := start
-	for _, testcase := range testcases {
-		if testcase.end.After(end) {
-			end = testcase.end
-		}
-	}
-	return end
-}
 
 // Report prints a report for TestSuites to the directory.  ftype == json | xml
 func (ts *Testsuites) Report(dir, name string, ftype Type) error {


Test patch:
diff --git a/pkg/report/report_test.go b/pkg/report/report_test.go
index 29eee6d..96228f3 100644
--- a/pkg/report/report_test.go
+++ b/pkg/report/report_test.go
@@ -36,9 +36,19 @@ AssertionError`,
 		Failures: 1,
 		Time:     "",
 		Name:     "github.com/kubebuilder/kuttl/pkg/version",
-		Testcase: []*Testcase{
+		Testcases: []*Testcase{
 			tcase,
 		},
+		SubSuites: []*Testsuite{
+			{
+				Tests:    7,
+				Failures: 1,
+				Name:     "sub-test-suite",
+				Testcases: []*Testcase{
+					tcase,
+				},
+			},
+		},
 	}
 
 	suites := Testsuites{
diff --git a/pkg/report/testdata/report.json.golden b/pkg/report/testdata/report.json.golden
index bbba0a4..cbab124 100644
--- a/pkg/report/testdata/report.json.golden
+++ b/pkg/report/testdata/report.json.golden
@@ -29,6 +29,27 @@
              "message": "test failure"
            }
          }
+       ],
+       "testsuite": [
+         {
+           "tests": 7,
+           "failures": 1,
+           "timestamp": "0001-01-01T00:00:00Z",
+           "time": "",
+           "name": "sub-test-suite",
+           "testcase": [
+             {
+               "classname": "pkg1.test.test_things",
+               "name": "test_params_func:2",
+               "timestamp": "0001-01-01T00:00:00Z",
+               "time": "",
+               "failure": {
+                 "text": "Traceback (most recent call last):\n  File \"nose2/plugins/loader/parameters.py\", line 162, in func\n    return obj(*argSet)\n  File \"nose2/tests/functional/support/scenario/tests_in_package/pkg1/test/test_things.py\", line 64, in test_params_func\n    assert a == 1\nAssertionError",
+                 "message": "test failure"
+               }
+             }
+           ]
+         }
        ]
      }
    ]
diff --git a/pkg/report/testdata/report.xml.golden b/pkg/report/testdata/report.xml.golden
index 8daf985..ffcd0a4 100644
--- a/pkg/report/testdata/report.xml.golden
+++ b/pkg/report/testdata/report.xml.golden
@@ -6,5 +6,10 @@
      <testcase classname="pkg1.test.test_things" name="test_params_func:2" timestamp="0001-01-01T00:00:00Z" time="" assertions="0">
        <failure message="test failure" type="">Traceback (most recent call last):&#xA;  File &#34;nose2/plugins/loader/parameters.py&#34;, line 162, in func&#xA;    return obj(*argSet)&#xA;  File &#34;nose2/tests/functional/support/scenario/tests_in_package/pkg1/test/test_things.py&#34;, line 64, in test_params_func&#xA;    assert a == 1&#xA;AssertionError</failure>
      </testcase>
+     <testsuite tests="7" failures="1" timestamp="0001-01-01T00:00:00Z" time="" name="sub-test-suite">
+       <testcase classname="pkg1.test.test_things" name="test_params_func:2" timestamp="0001-01-01T00:00:00Z" time="" assertions="0">
+         <failure message="test failure" type="">Traceback (most recent call last):&#xA;  File &#34;nose2/plugins/loader/parameters.py&#34;, line 162, in func&#xA;    return obj(*argSet)&#xA;  File &#34;nose2/tests/functional/support/scenario/tests_in_package/pkg1/test/test_things.py&#34;, line 64, in test_params_func&#xA;    assert a == 1&#xA;AssertionError</failure>
+       </testcase>
+     </testsuite>
    </testsuite>
  </testsuites>
\ No newline at end of file
diff --git a/pkg/test/case.go b/pkg/test/case.go
index bff8916..e17431d 100644
--- a/pkg/test/case.go
+++ b/pkg/test/case.go
@@ -314,12 +314,14 @@ func shortString(obj *corev1.ObjectReference) string {
 }
 
 // Run runs a test case including all of its steps.
-func (t *Case) Run(test *testing.T, tc *report.Testcase) {
+func (t *Case) Run(test *testing.T, ts *report.Testsuite) {
+	setupReport := report.NewCase("setup")
 	ns := t.determineNamespace()
 
 	cl, err := t.Client(false)
 	if err != nil {
-		tc.Failure = report.NewFailure(err.Error(), nil)
+		setupReport.Failure = report.NewFailure(err.Error(), nil)
+		ts.AddTestcase(setupReport)
 		test.Fatal(err)
 	}
 
@@ -332,7 +334,8 @@ func (t *Case) Run(test *testing.T, tc *report.Testcase) {
 
 		cl, err := newClient(testStep.Kubeconfig)(false)
 		if err != nil {
-			tc.Failure = report.NewFailure(err.Error(), nil)
+			setupReport.Failure = report.NewFailure(err.Error(), nil)
+			ts.AddTestcase(setupReport)
 			test.Fatal(err)
 		}
 
@@ -341,12 +344,15 @@ func (t *Case) Run(test *testing.T, tc *report.Testcase) {
 
 	for _, c := range clients {
 		if err := t.CreateNamespace(test, c, ns); err != nil {
-			tc.Failure = report.NewFailure(err.Error(), nil)
+			setupReport.Failure = report.NewFailure(err.Error(), nil)
+			ts.AddTestcase(setupReport)
 			test.Fatal(err)
 		}
 	}
+	ts.AddTestcase(setupReport)
 
 	for _, testStep := range t.Steps {
+		tc := report.NewCase("step " + testStep.String())
 		testStep.Client = t.Client
 		if testStep.Kubeconfig != "" {
 			testStep.Client = newClient(testStep.Kubeconfig)
@@ -359,7 +365,8 @@ func (t *Case) Run(test *testing.T, tc *report.Testcase) {
 		tc.Assertions += len(testStep.Asserts)
 		tc.Assertions += len(testStep.Errors)
 
-		if errs := testStep.Run(test, ns.Name); len(errs) > 0 {
+		errs := testStep.Run(test, ns.Name)
+		if len(errs) > 0 {
 			caseErr := fmt.Errorf("failed in step %s", testStep.String())
 			tc.Failure = report.NewFailure(caseErr.Error(), errs)
 
@@ -367,6 +374,9 @@ func (t *Case) Run(test *testing.T, tc *report.Testcase) {
 			for _, err := range errs {
 				test.Error(err)
 			}
+		}
+		ts.AddTestcase(tc)
+		if len(errs) > 0 {
 			break
 		}
 	}
diff --git a/pkg/test/case_integration_test.go b/pkg/test/case_integration_test.go
index a6bfe1d..83be4c8 100644
--- a/pkg/test/case_integration_test.go
+++ b/pkg/test/case_integration_test.go
@@ -111,5 +111,5 @@ func TestMultiClusterCase(t *testing.T) {
 		},
 	}
 
-	c.Run(t, &report.Testcase{})
+	c.Run(t, &report.Testsuite{})
 }
diff --git a/pkg/test/harness.go b/pkg/test/harness.go
index a4c1a7b..cd2a384 100644
--- a/pkg/test/harness.go
+++ b/pkg/test/harness.go
@@ -379,7 +379,7 @@ func (h *Harness) RunTests() {
 
 	h.T.Run("harness", func(t *testing.T) {
 		for testDir, tests := range realTestSuite {
-			suite := h.report.NewSuite(testDir)
+			suiteReport := h.report.NewSuite(testDir)
 			for _, test := range tests {
 				test := test
 
@@ -397,9 +397,8 @@ func (h *Harness) RunTests() {
 						t.Fatal(err)
 					}
 
-					tc := report.NewCase(test.Name)
-					test.Run(t, tc)
-					suite.AddTestcase(tc)
+					testReport := suiteReport.NewSubSuite(test.Name)
+					test.Run(t, testReport)
 				})
 			}
 		}