Detect if a `TestXYZ` is skipped

[maruina]

trafficstars

Hi all, I want to send a metric to report if a test is failing/successful.

The problem is-labels act upon features, and so the test is marked as successful even if we skip all the features inside it.

For example, given this snippet

	testenv.AfterEachTest(func(ctx context.Context, c *envconf.Config, t *testing.T) (context.Context, error) {
		t.Logf("Test %s is skipped: %v", t.Name(), t.Skipped())
		t.Logf("Test %s is failed: %v", t.Name(), t.Failed())
		return ctx, nil
	})

I get

❯ go test -v ./... -args -labels category=pod-native 
=== RUN   TestAzureRemoteVolume
=== PAUSE TestAzureRemoteVolume
=== RUN   TestPodNative
=== PAUSE TestPodNative
=== CONT  TestAzureRemoteVolume
=== CONT  TestPodNative
=== RUN   TestPodNative/basic_pod_native
=== RUN   TestAzureRemoteVolume/azure_remote_volume
=== RUN   TestPodNative/basic_pod_native/check_injected_environment_variables
=== NAME  TestAzureRemoteVolume/azure_remote_volume
    env.go:431: Skipping feature "azure remote volume": unmatched label "category=pod-native"
=== NAME  TestAzureRemoteVolume
    main_test.go:93: Test TestAzureRemoteVolume is skipped: false
    main_test.go:94: Test TestAzureRemoteVolume is failed: false
2023/02/24 11:55:46 Not reporting metrics to Datadog, ReportMetrics is disabled.
--- PASS: TestAzureRemoteVolume (0.00s)
    --- SKIP: TestAzureRemoteVolume/azure_remote_volume (0.00s)
=== NAME  TestPodNative
    main_test.go:93: Test TestPodNative is skipped: false
    main_test.go:94: Test TestPodNative is failed: false
2023/02/24 11:55:52 Not reporting metrics to Datadog, ReportMetrics is disabled.
--- PASS: TestPodNative (6.05s)
    --- PASS: TestPodNative/basic_pod_native (6.05s)
        --- PASS: TestPodNative/basic_pod_native/check_injected_environment_variables (6.05s)

So as you can see we can't detected between a skipped and failed test and we're reporting skewed metrics.

Do you have any suggestions about how we can fix/work around this? I could use -run regexp to select only the TestXYZ I'm interested about but then I'm losing all the benefit of labelling the tests and I would need a strong naming convention to do it.

I also looked into sending a metric per feature, but I don't think there is an easy way to say if that feature is successful or not.

[harshanarayana]

@maruina I did a quick scan and we do call the t.Skipf handlers in the execFeature which should have marked the right indicator for the Skip cases. Let me take a look and see if this needs a fix.

[maruina]

@harshanarayana thank you, please let me know if/how I can help

[maruina]

@harshanarayana did you have time to look into this? Is there anything I can do to help?

[harshanarayana]

Sorry I got a bit caught up with some personal work.. Will look into this over the weekend. In the mean time, if you can spare some time, please feel free to check the part where we perform t skips..

[harshanarayana]

I think I know why your expectations are not working.

package tskip_test

import (
	"context"
	"testing"

	"sigs.k8s.io/e2e-framework/pkg/envconf"
	"sigs.k8s.io/e2e-framework/pkg/features"
)

func TestOne(t *testing.T) {
	f1 := features.New("one").WithLabel("label", "abc").
		Assess("a1", func(ctx context.Context, t *testing.T, c *envconf.Config) context.Context {
			return ctx
		}).Assess("a2", func(ctx context.Context, t *testing.T, c *envconf.Config) context.Context {
		return ctx
	}).Feature()

	testEnv.Test(t, f1)
}

func TestTwo(t *testing.T) {
	f2 := features.New("two").WithLabel("label", "xyz").
		Assess("b1", func(ctx context.Context, t *testing.T, c *envconf.Config) context.Context {
			return ctx
		}).Assess("b2", func(ctx context.Context, t *testing.T, c *envconf.Config) context.Context {
		return ctx
	}).Feature()
	testEnv.Test(t, f2)
}

Take the above for example. With the Main defined as follwing

func TestMain(m *testing.M) {

	cfg, err := envconf.NewFromFlags()
	if err != nil {
		log.Fatalf("failed to load env config: %s", err)
	}

	testEnv = env.NewWithConfig(cfg)

	testEnv.AfterEachTest(func(ctx context.Context, c *envconf.Config, t *testing.T) (context.Context, error) {
		klog.InfoS("Test completed", "t", t.Name(), "skip", t.Skipped())
		return ctx, nil
	})

	os.Exit(testEnv.Run(m))
}

The AfterEachTest if you read the documentation says,

// AfterEachTest registers environment funcs that are executed // after each Env.Test(...).

So it kicks in only once for each test.

=== RUN   TestOne
=== RUN   TestOne/one
=== RUN   TestOne/one/a1
    env.go:451: Skipping assessment: "a1": name matched
=== RUN   TestOne/one/a2
I0326 18:22:08.279936   43302 main_test.go:26] "Test completed" t="TestOne" skip=false
--- PASS: TestOne (0.00s)
    --- PASS: TestOne/one (0.00s)
        --- SKIP: TestOne/one/a1 (0.00s)
        --- PASS: TestOne/one/a2 (0.00s)
=== RUN   TestTwo
=== RUN   TestTwo/two
=== RUN   TestTwo/two/b1
=== RUN   TestTwo/two/b2
I0326 18:22:08.280171   43302 main_test.go:26] "Test completed" t="TestTwo" skip=false
--- PASS: TestTwo (0.00s)
    --- PASS: TestTwo/two (0.00s)
        --- PASS: TestTwo/two/b1 (0.00s)
        --- PASS: TestTwo/two/b2 (0.00s)
PASS
ok  	sigs.k8s.io/e2e-framework/examples/tskip	1.350s

So I went around digging for a it a bit more by adding some more log and context.

diff --git a/pkg/env/env.go b/pkg/env/env.go
index ad23f10..a4483af 100644
--- a/pkg/env/env.go
+++ b/pkg/env/env.go
@@ -210,6 +210,7 @@ func (e *testEnv) processTestFeature(t *testing.T, featureName string, feature t
 	// execute feature test
 	e.ctx = e.execFeature(e.ctx, t, featureName, feature)
 
+	klog.InfoS("After test exec feature", "t", t.Name(), "test", fmt.Sprintf("%p", t), "skip", t.Skipped())
 	// execute afterEachFeature actions
 	e.processFeatureActions(t, feature, e.getAfterFeatureActions())
 }
@@ -428,10 +429,10 @@ func (e *testEnv) execFeature(ctx context.Context, t *testing.T, featName string
 	// feature-level subtest
 	t.Run(featName, func(t *testing.T) {
 		skipped, message := e.requireFeatureProcessing(f)
+		klog.InfoS("Execute Feature", "test", t.Name(), "t", fmt.Sprintf("%p", t))
 		if skipped {
 			t.Skipf(message)
 		}
-
 		// setups run at feature-level
 		setups := features.GetStepsByLevel(f.Steps(), types.LevelSetup)
 		ctx = e.executeSteps(ctx, t, setups)
@@ -447,6 +448,7 @@ func (e *testEnv) execFeature(ctx context.Context, t *testing.T, featName string
 			}
 			t.Run(assessName, func(t *testing.T) {
 				skipped, message := e.requireAssessmentProcessing(assess, i+1)
+				klog.InfoS("Execute Assessment", "test", t.Name(), "t", fmt.Sprintf("%p", t))
 				if skipped {
 					t.Skipf(message)
 				}

// some_test.go
func TestOne(t *testing.T) {
	klog.InfoS("Starting Test", "test", t.Name(), "t", fmt.Sprintf("%p", t))
	f1 := features.New("one").WithLabel("label", "abc").
		Assess("a1", func(ctx context.Context, t *testing.T, c *envconf.Config) context.Context {
			return ctx
		}).Assess("a2", func(ctx context.Context, t *testing.T, c *envconf.Config) context.Context {
		return ctx
	}).Feature()

	testEnv.Test(t, f1)
}

func TestTwo(t *testing.T) {
	klog.InfoS("Starting Test", "test", t.Name(), "t", fmt.Sprintf("%p", t))
	f2 := features.New("two").WithLabel("label", "xyz").
		Assess("b1", func(ctx context.Context, t *testing.T, c *envconf.Config) context.Context {
			return ctx
		}).Assess("b2", func(ctx context.Context, t *testing.T, c *envconf.Config) context.Context {
		return ctx
	}).Feature()
	testEnv.Test(t, f2)
}

# main_test.go
func TestMain(m *testing.M) {

	cfg, err := envconf.NewFromFlags()
	if err != nil {
		log.Fatalf("failed to load env config: %s", err)
	}

	testEnv = env.NewWithConfig(cfg)

	testEnv.BeforeEachTest(func(ctx context.Context, c *envconf.Config, t *testing.T) (context.Context, error) {
		klog.InfoS("Before Each Test", "t", t.Name(), "skip", t.Skipped(), "test", fmt.Sprintf("%p", t))
		return ctx, nil
	})

	testEnv.BeforeEachFeature(func(ctx context.Context, c *envconf.Config, t *testing.T, f features.Feature) (context.Context, error) {
		klog.InfoS("Before Each Feature", "t", t.Name(), "skip", t.Skipped(), "test", fmt.Sprintf("%p", t))
		return ctx, nil
	})

	testEnv.AfterEachTest(func(ctx context.Context, c *envconf.Config, t *testing.T) (context.Context, error) {
		klog.InfoS("After Each Test", "t", t.Name(), "skip", t.Skipped(), "test", fmt.Sprintf("%p", t))
		return ctx, nil
	})

	testEnv.AfterEachFeature(func(ctx context.Context, c *envconf.Config, t *testing.T, f features.Feature) (context.Context, error) {
		klog.InfoS("After Each Feature", "t", t.Name(), "skip", t.Skipped(), "test", fmt.Sprintf("%p", t))
		return ctx, nil
	})

	os.Exit(testEnv.Run(m))
}

And here is what I found

❯ go test -v . -args --skip-labels "label=abc"
=== RUN   TestOne
I0327 14:24:39.175823   89197 some_test.go:14] "Starting Test" test="TestOne" t="0xc000802ea0"
I0327 14:24:39.176072   89197 main_test.go:28] "Before Each Test" t="TestOne" skip=false test="0xc000802ea0"
I0327 14:24:39.176081   89197 main_test.go:33] "Before Each Feature" t="TestOne" skip=false test="0xc000802ea0"
=== RUN   TestOne/one
I0327 14:24:39.176172   89197 env.go:432] "Execute Feature" test="TestOne/one" t="0xc0008031e0"
    env.go:434: Skipping feature "one": matched label provided in --skip-lables "label=[abc]"
I0327 14:24:39.176220   89197 env.go:213] "After test exec feature" t="TestOne" test="0xc000802ea0" skip=false
I0327 14:24:39.176228   89197 main_test.go:43] "After Each Feature" t="TestOne" skip=false test="0xc000802ea0"
I0327 14:24:39.176233   89197 main_test.go:38] "After Each Test" t="TestOne" skip=false test="0xc000802ea0"
--- PASS: TestOne (0.00s)
    --- SKIP: TestOne/one (0.00s)
=== RUN   TestTwo
I0327 14:24:39.176281   89197 some_test.go:26] "Starting Test" test="TestTwo" t="0xc000803520"
I0327 14:24:39.176298   89197 main_test.go:28] "Before Each Test" t="TestTwo" skip=false test="0xc000803520"
I0327 14:24:39.176308   89197 main_test.go:33] "Before Each Feature" t="TestTwo" skip=false test="0xc000803520"
=== RUN   TestTwo/two
I0327 14:24:39.176370   89197 env.go:432] "Execute Feature" test="TestTwo/two" t="0xc0008036c0"
=== RUN   TestTwo/two/b1
I0327 14:24:39.176405   89197 env.go:451] "Execute Assessment" test="TestTwo/two/b1" t="0xc000803860"
=== RUN   TestTwo/two/b2
I0327 14:24:39.176430   89197 env.go:451] "Execute Assessment" test="TestTwo/two/b2" t="0xc000803ba0"
I0327 14:24:39.176445   89197 env.go:213] "After test exec feature" t="TestTwo" test="0xc000803520" skip=false
I0327 14:24:39.176454   89197 main_test.go:43] "After Each Feature" t="TestTwo" skip=false test="0xc000803520"
I0327 14:24:39.176462   89197 main_test.go:38] "After Each Test" t="TestTwo" skip=false test="0xc000803520"
--- PASS: TestTwo (0.00s)
    --- PASS: TestTwo/two (0.00s)
        --- PASS: TestTwo/two/b1 (0.00s)
        --- PASS: TestTwo/two/b2 (0.00s)
PASS
ok  	sigs.k8s.io/e2e-framework/examples/tskip	0.675s

1. The t passed to the TestOne is getting passed down to the env.go until execFeature
2. In execFeature handler the t.Skip is done on a closure handler so it is an entirely different object that is actually getting skipped than the one being passed to the AfterEach{context} handlers

[harshanarayana]

I am not still done with this analysis. Will post a bit more context today or tomorrow. This is not fully done yet.

[vladimirvivien]

@harshanarayana @maruina this sound like an issue we need to keep an eye on. If you have any update, please post.

[maruina]

Hey @vladimirvivien, I don't have any update yet but I'll ping you when I have time to look into this

[k8s-triage-robot]

The Kubernetes project currently lacks enough contributors to adequately respond to all issues.

This bot triages un-triaged issues according to the following rules:

• After 90d of inactivity, lifecycle/stale is applied
• After 30d of inactivity since lifecycle/stale was applied, lifecycle/rotten is applied
• After 30d of inactivity since lifecycle/rotten was applied, the issue is closed

You can:

• Mark this issue as fresh with /remove-lifecycle stale
• Close this issue with /close
• Offer to help out with Issue Triage

Please send feedback to sig-contributor-experience at kubernetes/community.

/lifecycle stale

[vladimirvivien]

@harshanarayana and @maruina This seems like it fell off the radar.

/remove-lifecycle stale

[maruina]

Yes, I think it's something still worth addressing. I will try to find some time to look into it