Repository: kudobuilder/kuttl
Pull request #223 (2020-10-09 14:55:41)

Include precise test case start in report output
**What this PR does / why we need it**:

- rename `TestSuite.start` to `TestSuite.Timestamp` so that it is reported according to schema which says this is a required field
- rename `TestCase.start` to `TestCase.Timestamp` to also get the time for each test case. This is not in the schema, but should not hurt
- move the call to `testing.T.Parallel()` a bit earlier, so that the time measurements are not affected by it blocking

TL;DR: see PR subject

Background:

I'm doing capacity planning of a growing test suite. The high-level
quesiton I need to answer is: what cluster size to use for a given level of
parallelism of kuttl test cases to make sure that they can all pass.

Caveat: some of our cases *will deadlock* with each other when insufficient
resources are present on the cluster. They should probably use some form of
gang scheduling to avoid this problem, but currently they don't and it's not
under our control. So back to capacity planning.

In order to do that, I need to discover resource usage for each test case
separately. I have the resource monitoring covered, and I can run with disabled
parallelism for the purpose of data collection, but in order to attribute given
usage to the name of the test case in progress, I need to be able to reliably
and rather precisely tell when a given test case starts and stops.



porridge: Oh, and another alternative I thought about is changing the existing format, but screen real estate is too precious...
kensipe: thoughts...

first... great thinking!
months ago I had some similar thoughts but I think we are looking at from different angles... yours is more data driven which I like a lot but also requires some history of testing to determine optimization.
What I was thinking was establishing at a TestSuite level required minimum expectations for that TestSuite to run.  So if it is known by the author of the tests that for the tests to run it requires 3 nodes... then the tests will be skipped for clusters of < 3 nodes...  Other resource requirements acting the same (GPU, total concurrent cpu or max cpu requirement (like I need to land on a 8 core box)).
Personally I think both approaches are worth consideration.

That aside, I really like the PR for timing.   I believe we already have timing information.  if you use the `--report` flag there are times for test collections, test suites and individual tests as shown here: https://github.com/kudobuilder/kuttl/pull/128

```
 <testsuites name="" tests="10" failures="1" time="16.655560703s">
   <testsuite tests="10" failures="1" time="11.770504224s" name="pkg/test/test_data/">
     <testcase classname="test_data" name="list-pods" time="67.649654ms" assertions="1"></testcase>
     <testcase classname="test_data" name="teststep-assert" time="182.35219ms" assertions="2"></testcase>
     <testcase classname="test_data" name="teststep-errors" time="217.915925ms" assertions="4"></testcase>
     <testcase classname="test_data" name="teststep-apply" time="292.566614ms" assertions="2"></testcase>
     <testcase classname="test_data" name="delete-in-step" time="681.225526ms" assertions="4"></testcase>
     <testcase classname="test_data" name="create-or-update" time="844.747083ms" assertions="7"></testcase>
     <testcase classname="test_data" name="with-overrides" time="1.138570835s" assertions="4"></testcase>
     <testcase classname="test_data" name="crd-in-step" time="1.781726862s" assertions="2"></testcase>
     <testcase classname="test_data" name="deprecate-test" time="1.799839758s" assertions="2"></testcase>
     <testcase classname="test_data" name="cli-test" time="11.769091322s" assertions="2">
       <failure message="failed in step 1-patch" type="">resource Pod:kudo-test-suited-tomcat/cli-test-pod: .metadata.labels.test: value mismatch, expected: false != actual: true</failure>
     </testcase>
   </testsuite>
 </testsuites>
```

I believe the testsuite time is a calculated time (vs measured)... I think it takes the earliest testcase time and the latest testcase end time.  Same with test collections (named `testsuites` with an `s` at the end in the output)

Lets talk about if this fits your need or if we need to add more... or if there is more value in the log file instead of a report file.
porridge: My longed-term term goal goes along the lines of your thoughts, but even a bit further. If we could annotate test cases with their resource requirements, and also give the harness some idea about available resources, it would be possible to have the harness automatically compute the maximum parallelism level, and schedule cases such that total resource consumption at any given moment would always be below the available amount.

The auto-generated parallelism level could even potentially be variable, since the distribution of resource consumption is usually far from uniform. Here is the data from my suite:

![Zrzut ekranu z 2020-10-12 06-46-18](https://user-images.githubusercontent.com/489420/95706273-b5197f80-0c56-11eb-91d7-2fdd25434934.png)

This way, the parallelism would increase when the less resource-hungry tests are run, optimizing run time and utilization, minimizing waste.

But as I said, step zero is discovering the actual resource consumption so that the test creator has something to annotate the tests with :slightly_smiling_face: 

So back to reporting the data:

I *knew* there was support for reporting this, but could not find it! It's well hidden!
Hits from [[site:kuttl.dev report]](https://www.google.com/search?client=firefox-b-1-e&q=site%3Akuttl.dev+report) are not useful, and help is also silent:
```
$ kubectl kuttl help test|grep report
$ kubectl kuttl help |grep report
$
```

I took a look at the report schema, and it already seems to have *most* of what I need, is machine-readable and this way does not need to pollute the log!
The windyroad schema seems very strict, but I found [evidence](https://community.atlassian.com/t5/Bamboo-questions/JUnit-XML-schema/qaq-p/769965) that even some big players take it with a grain of salt. I'm going to change this PR to adjust the report output a little.
kensipe: I'll get on adding reports to doc site and increasing exposure to CLI.  that's a great point.

regarding xml format...  there are 2 drivers there... 1.  it was specifically requested by a user (operator-sdk scorecard which uses it).  2. all CI tools I know of have a way of displaying this information... which is why there are converters to it from other languages... it is strange that junit xml == java unit tests xml output... however there are lots of languages that convert to the "java" report... which is why https://github.com/jstemmer/go-junit-report is popular.   i guess it is first rights.

While the go-junit-report is popular it is dependent on the `go test` output which kuttl does not maintain. 
kensipe: looking into this... perhaps there is an older version being used.  I get report on the latest:
```
 k kuttl help test | grep report
      --report string                 Specify JSON|XML for report.  Report location determined by --artifacts-dir.
```
I still plan on raising more awareness
kensipe: https://github.com/kudobuilder/kuttl/pull/227

porridge: > looking into this... perhaps there is an older version being used. I get report on the latest:
> 
> ```
>  k kuttl help test | grep report
>       --report string                 Specify JSON|XML for report.  Report location determined by --artifacts-dir.
> ```

You're right. Outside of the testing container I have `v0.4.0` which is the most recent in `krew` index :cry: 
porridge: I changed the implementation to include the timestamps in the report output rather than logs.
It's even easier to ingest for my purpose.
WDYT @kensipe ?

Patch:
diff --git a/pkg/report/report.go b/pkg/report/report.go
index 1494fa8..654e213 100644
--- a/pkg/report/report.go
+++ b/pkg/report/report.go
@@ -16,23 +16,23 @@ import (
 // KUTTL is different than junit testing in that the test steps could be useful to have a report on.  There could be value in
 // having a TestCaseStep struct providing step details.  Sticking with the JUnit standard for now.
 
-// Type defines the report.type of report to create
+// Type defines the report.type of report to create.
 type Type string
 
 const (
-	// XML defines the xml Type
+	// XML defines the xml Type.
 	XML Type = "xml"
-	// JSON defines the json Type
+	// JSON defines the json Type.
 	JSON Type = "json"
 )
 
-// Property are name/value pairs which can be provided in the report for things such as kuttl.version
+// Property are name/value pairs which can be provided in the report for things such as kuttl.version.
 type Property struct {
 	Name  string `xml:"name,attr" json:"name"`
 	Value string `xml:"value,attr" json:"value"`
 }
 
-// Properties defines the collection of properties
+// Properties defines the collection of properties.
 type Properties struct {
 	Property []Property `xml:"property" json:"property,omitempty"`
 }
@@ -41,46 +41,49 @@ type Properties struct {
 type Failure struct {
 	// Text provides detailed information regarding failure.  It supports multi-line output.
 	Text string `xml:",chardata" json:"text,omitempty"`
-	// Message provides the summary of the failure
+	// Message provides the summary of the failure.
 	Message string `xml:"message,attr" json:"message"`
 	Type    string `xml:"type,attr" json:"type,omitempty"`
 }
 
-// Testcase is the finest grain level of reporting, it is the kuttl test (which contains steps)
+// Testcase is the finest grain level of reporting, it is the kuttl test (which contains steps).
 type Testcase struct {
-	// Classname is a junit thing, for kuttl it is the testsuite name
+	// Classname is a junit thing, for kuttl it is the testsuite name.
 	Classname string `xml:"classname,attr" json:"classname"`
-	// Name is the name of the test (folder of test if not redefined by the TestStep)
+	// Name is the name of the test (folder of test if not redefined by the TestStep).
 	Name string `xml:"name,attr" json:"name"`
-	// Time is the elapsed time of the test (and all of it's steps)
+	// Timestamp is the time when this Testcase started.
+	// This attribute is not in the mentioned XML schema (unlike Testsuite.Timestamp) but should be
+	// gracefully ignored by readers who do not expect it.
+	Timestamp time.Time `xml:"timestamp,attr" json:"timestamp"`
+	// Time is the elapsed time of the test (and all of its steps).
 	Time string `xml:"time,attr" json:"time"`
-	// Assertions is the number of asserts and errors defined in the test
+	// Assertions is the number of asserts and errors defined in the test.
 	Assertions int `xml:"assertions,attr" json:"assertions,omitempty"`
-	// Failure defines a failure in this testcase
+	// Failure defines a failure in this Testcase.
 	Failure *Failure `xml:"failure" json:"failure,omitempty"`
 
-	// start and end are not reported.  They are used to calc duration times for testcase and testsuite.
-	start time.Time
-	end   time.Time
+	// end is not reported.  It is used to calculate duration times for testcase and testsuite.
+	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 is the number of Testcases in the collection.
 	Tests int `xml:"tests,attr" json:"tests"`
-	// Failures is the summary number of all failure in the collection testcases
+	// Failures is the summary number of all failure in the collection testcases.
 	Failures int `xml:"failures,attr" json:"failures"`
+	// Timestamp is the time when this Testsuite started.
+	Timestamp time.Time `xml:"timestamp,attr" json:"timestamp"`
 	// Time is the duration of time for this Testsuite, this is tricky as tests run concurrently.
 	// This is the elapse time between the start of the testsuite and the end of the latest testcase in the collection.
 	Time string `xml:"time,attr" json:"time"`
-	// Name is the kuttl test name
+	// Name is the kuttl test name.
 	Name string `xml:"name,attr" json:"name"`
-	// Properties which are specific to this suite
+	// Properties which are specific to this suite.
 	Properties *Properties `xml:"properties" json:"properties,omitempty"`
-	// Testcase is a collection of test cases
+	// Testcase is a collection of test cases.
 	Testcase []*Testcase `xml:"testcase" json:"testcase,omitempty"`
-
-	start time.Time
 }
 
 // Testsuites is a collection of Testsuite and defines the rollup summary of all stats.
@@ -89,15 +92,15 @@ type Testsuites struct {
 	XMLName xml.Name `json:"-"`
 	// Name is the name of the full set of tests which is possible to set in kuttl but is rarely used :)
 	Name string `xml:"name,attr" json:"name"`
-	// Tests is a summary value of the total number of tests for all testsuites
+	// Tests is a summary value of the total number of tests for all testsuites.
 	Tests int `xml:"tests,attr" json:"tests"`
-	// Failures is a summary value of the total number of failures for all testsuites
+	// Failures is a summary value of the total number of failures for all testsuites.
 	Failures int `xml:"failures,attr" json:"failures"`
-	// Time is the elapsed time of the entire suite of tests
+	// Time is the elapsed time of the entire suite of tests.
 	Time string `xml:"time,attr" json:"time"`
-	// Properties which are for the entire set of tests
+	// Properties which are for the entire set of tests.
 	Properties *Properties `xml:"properties" json:"properties,omitempty"`
-	// Testsuite is a collection of test suites
+	// Testsuite is a collection of test suites.
 	Testsuite []*Testsuite `xml:"testsuite" json:"testsuite,omitempty"`
 
 	start time.Time
@@ -112,13 +115,13 @@ func NewSuiteCollection(name string) *Testsuites {
 // NewSuite returns the address of a newly created TestSuite
 func NewSuite(name string) *Testsuite {
 	start := time.Now()
-	return &Testsuite{Name: name, start: start}
+	return &Testsuite{Name: name, Timestamp: start}
 }
 
 // NewCase returns the address of a newly create Testcase
 func NewCase(name string) *Testcase {
 	start := time.Now()
-	return &Testcase{Name: name, start: start}
+	return &Testcase{Name: name, Timestamp: start}
 }
 
 // NewFailure returns the address of a newly created Failure
@@ -139,7 +142,7 @@ func NewFailure(msg string, errs []error) *Failure {
 func (ts *Testsuite) AddTestcase(testcase *Testcase) {
 	// this is needed to calc elapse time of testsuite in a async work
 	testcase.end = time.Now()
-	elapsed := time.Since(testcase.start)
+	elapsed := time.Since(testcase.Timestamp)
 	testcase.Time = fmt.Sprintf("%.3f", elapsed.Seconds())
 	testcase.Classname = filepath.Base(ts.Name)
 
@@ -189,7 +192,7 @@ func (ts *Testsuites) Close() {
 
 	// async work makes this necessary (stats for each testsuite)
 	for _, testsuite := range ts.Testsuite {
-		elapsed = latestEnd(testsuite.start, testsuite.Testcase).Sub(testsuite.start)
+		elapsed = latestEnd(testsuite.Timestamp, testsuite.Testcase).Sub(testsuite.Timestamp)
 		testsuite.Time = fmt.Sprintf("%.3f", elapsed.Seconds())
 
 		ts.Tests += testsuite.Tests


Test patch:
diff --git a/pkg/kuttlctl/cmd/test.go b/pkg/kuttlctl/cmd/test.go
index 52549e6..c62b99d 100644
--- a/pkg/kuttlctl/cmd/test.go
+++ b/pkg/kuttlctl/cmd/test.go
@@ -71,7 +71,7 @@ The test operator supports connecting to an existing Kubernetes cluster or it ca
 It can also apply manifests before running the tests. If no arguments are provided, the test harness will attempt to
 load the test configuration from kuttl-test.yaml.
 
-For more detailed documentation, visit: https://kudo.dev/docs/testing`,
+For more detailed documentation, visit: https://kuttl.dev`,
 		Example: testExample,
 		PreRunE: func(cmd *cobra.Command, args []string) error {
 			flags := cmd.Flags()
diff --git a/pkg/report/testdata/report.json.golden b/pkg/report/testdata/report.json.golden
index 86e7086..bbba0a4 100644
--- a/pkg/report/testdata/report.json.golden
+++ b/pkg/report/testdata/report.json.golden
@@ -15,12 +15,14 @@
      {
        "tests": 9,
        "failures": 1,
+       "timestamp": "0001-01-01T00:00:00Z",
        "time": "",
        "name": "github.com/kubebuilder/kuttl/pkg/version",
        "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",
diff --git a/pkg/report/testdata/report.xml.golden b/pkg/report/testdata/report.xml.golden
index 4616507..8daf985 100644
--- a/pkg/report/testdata/report.xml.golden
+++ b/pkg/report/testdata/report.xml.golden
@@ -2,8 +2,8 @@
    <properties>
      <property name="go.version" value="1.14"></property>
    </properties>
-   <testsuite tests="9" failures="1" time="" name="github.com/kubebuilder/kuttl/pkg/version">
-     <testcase classname="pkg1.test.test_things" name="test_params_func:2" time="" assertions="0">
+   <testsuite tests="9" failures="1" timestamp="0001-01-01T00:00:00Z" time="" name="github.com/kubebuilder/kuttl/pkg/version">
+     <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>
diff --git a/pkg/test/case.go b/pkg/test/case.go
index 4a5f2f9..c942fe6 100644
--- a/pkg/test/case.go
+++ b/pkg/test/case.go
@@ -194,8 +194,6 @@ 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) {
-	test.Parallel()
-
 	ns := t.determineNamespace()
 	if err := t.CreateNamespace(ns); err != nil {
 		test.Fatal(err)
@@ -250,7 +248,7 @@ func (t *Case) determineNamespace() *namespace {
 	}
 	// no preferred ns, means we auto-create with petnames
 	if t.PreferredNamespace == "" {
-		ns.Name = fmt.Sprintf("kudo-test-%s", petname.Generate(2, "-"))
+		ns.Name = fmt.Sprintf("kuttl-test-%s", petname.Generate(2, "-"))
 		ns.AutoCreated = true
 	}
 	// if we have a preferred namespace, we do NOT auto-create
diff --git a/pkg/test/harness.go b/pkg/test/harness.go
index b9032fd..f139739 100644
--- a/pkg/test/harness.go
+++ b/pkg/test/harness.go
@@ -368,6 +368,10 @@ func (h *Harness) RunTests() {
 				test.DiscoveryClient = h.DiscoveryClient
 
 				t.Run(test.Name, func(t *testing.T) {
+					// testing.T.Parallel may block, so run it before we read time for our
+					// elapsed time calculations.
+					t.Parallel()
+
 					test.Logger = testutils.NewTestLogger(t, test.Name)
 
 					if err := test.LoadTestSteps(); err != nil {
diff --git a/pkg/test/step_integration_test.go b/pkg/test/step_integration_test.go
index c4967cc..a9ddaa6 100644
--- a/pkg/test/step_integration_test.go
+++ b/pkg/test/step_integration_test.go
@@ -232,7 +232,7 @@ func TestCheckResourceIntegration(t *testing.T) {
 		},
 	} {
 		t.Run(test.testName, func(t *testing.T) {
-			namespace := fmt.Sprintf("kudo-test-%s", petname.Generate(2, "-"))
+			namespace := fmt.Sprintf("kuttl-test-%s", petname.Generate(2, "-"))
 
 			err := testenv.Client.Create(context.TODO(), testutils.NewResource("v1", "Namespace", namespace, ""))
 			if !k8serrors.IsAlreadyExists(err) {
@@ -404,7 +404,7 @@ func TestStepFailure(t *testing.T) {
 		},
 	}
 
-	namespace := fmt.Sprintf("kudo-test-%s", petname.Generate(2, "-"))
+	namespace := fmt.Sprintf("kuttl-test-%s", petname.Generate(2, "-"))
 
 	err := testenv.Client.Create(context.TODO(), testutils.NewResource("v1", "Namespace", namespace, ""))
 	if !k8serrors.IsAlreadyExists(err) {
diff --git a/pkg/test/utils/kubernetes.go b/pkg/test/utils/kubernetes.go
index 8aa3f42..def7130 100644
--- a/pkg/test/utils/kubernetes.go
+++ b/pkg/test/utils/kubernetes.go
@@ -392,6 +392,9 @@ func ConvertUnstructured(in runtime.Object) (runtime.Object, error) {
 	// Deprecated: kudo.dev is deprecated.
 	kudoGroup := "kudo.dev"
 	kuttlGroup := "kuttl.dev"
+	if group == kudoGroup {
+		log.Print("WARNING: kudo.dev group has been deprecated and is schedule to be removed in KUTTL 0.8.0")
+	}
 	if (group == kudoGroup || group == kuttlGroup) && kind == "TestStep" {
 		converted = &harness.TestStep{}
 	} else if (group == kudoGroup || group == kuttlGroup) && kind == "TestAssert" {
@@ -1043,10 +1046,10 @@ func RunCommand(ctx context.Context, namespace string, cmd harness.Command, cwd
 		return nil, fmt.Errorf("command %q with %w", cmd.Command, err)
 	}
 
-	kudoENV := make(map[string]string)
-	kudoENV["NAMESPACE"] = namespace
-	kudoENV["KUBECONFIG"] = fmt.Sprintf("%s/kubeconfig", actualDir)
-	kudoENV["PATH"] = fmt.Sprintf("%s/bin/:%s", actualDir, os.Getenv("PATH"))
+	kuttlENV := make(map[string]string)
+	kuttlENV["NAMESPACE"] = namespace
+	kuttlENV["KUBECONFIG"] = fmt.Sprintf("%s/kubeconfig", actualDir)
+	kuttlENV["PATH"] = fmt.Sprintf("%s/bin/:%s", actualDir, os.Getenv("PATH"))
 
 	// by default testsuite timeout is the command timeout
 	// 0 is allowed for testsuite which means forever (or no timeout)
@@ -1070,7 +1073,7 @@ func RunCommand(ctx context.Context, namespace string, cmd harness.Command, cwd
 		defer cancel()
 	}
 
-	builtCmd, err := GetArgs(cmdCtx, cmd, namespace, kudoENV)
+	builtCmd, err := GetArgs(cmdCtx, cmd, namespace, kuttlENV)
 	if err != nil {
 		return nil, fmt.Errorf("processing command %q with %w", cmd.Command, err)
 	}
@@ -1083,7 +1086,7 @@ func RunCommand(ctx context.Context, namespace string, cmd harness.Command, cwd
 		builtCmd.Stderr = stderr
 	}
 	builtCmd.Env = os.Environ()
-	for key, value := range kudoENV {
+	for key, value := range kuttlENV {
 		builtCmd.Env = append(builtCmd.Env, fmt.Sprintf("%s=%s", key, value))
 	}