From 1d9e14191ccd795d2aecf9b5810527218926b163 Mon Sep 17 00:00:00 2001 From: Nir Soffer Date: Wed, 27 Nov 2024 02:33:59 +0200 Subject: [PATCH] e2e: Log errors This is an alternative to #1596, trying to keep the test code more idiomatic, cleaner, and easier to use correctly. Add e2e/test.T type, embedding the standard library *testing.T, and keeping a logger. This type overrides testing.T methods logging to the standard library logger with methods logging to the specific logger. The Fatal[f] and Error[]f methods log an ERROR messages to make errors easy to find. To use the our T type, a test need to wrap the standard library *testing.T with the per-test logger: func TestFoo(dt *testing.T) { t := e2etesting.WithLog(dt, ctx.Logger()) Now we can use t transparently in this test: t.Log("This logs an INFO message to our logger") Note that the wrapped Error() and Fatal() method accept an error and will log a stracktrace: if err := ...; err != nil { // Log an error with a stracktrace and mark the test as failed. t.Error(err, "Failed, trying next step") } if err := ...; err != nil { // Log an error with a stracktrace and fail the test immediately. t.Fatal(err, "Failed, cannot continue") } Example error log (wrapped for readability): 2024-11-29T03:12:32.837+0200 ERROR subscr-deploy-rbd-busybox test/testing.go:55 Failed to failover workload: fake error in waitAndUpdateDRPC: failover to cluster "dr1" github.com/ramendr/ramen/e2e/test.(*T).Fatalf /Users/nsoffer/src/ramen/e2e/test/testing.go:55 github.com/ramendr/ramen/e2e/test.(*Context).Failover /Users/nsoffer/src/ramen/e2e/test/context.go:102 testing.tRunner /opt/homebrew/Cellar/go/1.23.3/libexec/src/testing/testing.go:1690 Notes: - All the test functions were updated to accept a `*testing.T` and wrap it with per-test log. Test helper functions accept now a `*e2e/test.T` so they don't need extra wrapping. - Sub tests requires wrapping the standard library t again, since testing.T is a type, not an interface. This adds one line of boilerplate for every sub test. - All Error[f] and Fatal[f] calls changed to format an error message with the underlying error so we should get more helpful error messages when something fails deep in the utility functions. - When DR sub test (e.g. Deploy) fails, we already logged the error by failing the sub test, so we call FailNow() in the parent test to abort the parent test silently. Issues: - The stracktrace does not include all callers leading the point the error was created, since fmt.Errorf() does not capture the stack. We can get better stacktrace by using another error package that does this like https://pkg.go.dev/github.com/go-errors/errors. - We need to disable the `thelper` linter in test.Context to allow using `dt *testing.T` and keep the test code idiomatic. Another way is to keep `t *testing.T`, and use `et` for the wrapped t. This makes the test code less idiomatic but it may be more clear that this is a non standard `t`. Fixes: #1595 Signed-off-by: Nir Soffer --- e2e/exhaustive_suite_test.go | 25 +++++++------ e2e/main_test.go | 8 +++-- e2e/test/context.go | 31 +++++++++------- e2e/test/testing.go | 69 ++++++++++++++++++++++++++++++++++++ e2e/validation_suite_test.go | 22 ++++++++---- 5 files changed, 122 insertions(+), 33 deletions(-) create mode 100644 e2e/test/testing.go diff --git a/e2e/exhaustive_suite_test.go b/e2e/exhaustive_suite_test.go index 22e6e8696..5a17d46d1 100644 --- a/e2e/exhaustive_suite_test.go +++ b/e2e/exhaustive_suite_test.go @@ -63,17 +63,19 @@ func generateWorkloads([]types.Workload) { } } -func Exhaustive(t *testing.T) { +// nolint: thelper +func Exhaustive(dt *testing.T) { + t := test.WithLog(dt, util.Ctx.Log) t.Helper() t.Parallel() if err := util.EnsureChannel(); err != nil { - t.Fatalf("failed to ensure channel: %v", err) + t.Fatalf("Failed to ensure channel: %s", err) } t.Cleanup(func() { if err := util.EnsureChannelDeleted(); err != nil { - t.Fatalf("failed to ensure channel deleted: %v", err) + t.Fatalf("Failed to ensure channel deleted: %s", err) } }) @@ -82,7 +84,8 @@ func Exhaustive(t *testing.T) { for _, deployer := range Deployers { for _, workload := range Workloads { ctx := test.NewContext(workload, deployer, util.Ctx.Log) - t.Run(ctx.Name(), func(t *testing.T) { + t.Run(ctx.Name(), func(dt *testing.T) { + t := test.WithLog(dt, ctx.Logger()) t.Parallel() runTestFlow(t, ctx) }) @@ -90,7 +93,7 @@ func Exhaustive(t *testing.T) { } } -func runTestFlow(t *testing.T, ctx test.Context) { +func runTestFlow(t *test.T, ctx test.Context) { t.Helper() if err := ctx.Validate(); err != nil { @@ -98,26 +101,26 @@ func runTestFlow(t *testing.T, ctx test.Context) { } if !t.Run("Deploy", ctx.Deploy) { - t.Fatal("Deploy failed") + t.FailNow() } if !t.Run("Enable", ctx.Enable) { - t.Fatal("Enable failed") + t.FailNow() } if !t.Run("Failover", ctx.Failover) { - t.Fatal("Failover failed") + t.FailNow() } if !t.Run("Relocate", ctx.Relocate) { - t.Fatal("Relocate failed") + t.FailNow() } if !t.Run("Disable", ctx.Disable) { - t.Fatal("Disable failed") + t.FailNow() } if !t.Run("Undeploy", ctx.Undeploy) { - t.Fatal("Undeploy failed") + t.FailNow() } } diff --git a/e2e/main_test.go b/e2e/main_test.go index 94bd96d3f..ef8472512 100644 --- a/e2e/main_test.go +++ b/e2e/main_test.go @@ -8,6 +8,7 @@ import ( "os" "testing" + "github.com/ramendr/ramen/e2e/test" "github.com/ramendr/ramen/e2e/util" uberzap "go.uber.org/zap" "go.uber.org/zap/zapcore" @@ -53,11 +54,12 @@ var Suites = []testDef{ {"Exhaustive", Exhaustive}, } -func TestSuites(t *testing.T) { - util.Ctx.Log.Info(t.Name()) +func TestSuites(dt *testing.T) { + t := test.WithLog(dt, util.Ctx.Log) + t.Log(t.Name()) if !t.Run("Validate", Validate) { - t.Fatal("failed to validate the test suite") + t.FailNow() } for _, suite := range Suites { diff --git a/e2e/test/context.go b/e2e/test/context.go index 3fd156203..a0ed07f4b 100644 --- a/e2e/test/context.go +++ b/e2e/test/context.go @@ -1,6 +1,7 @@ // SPDX-FileCopyrightText: The RamenDR authors // SPDX-License-Identifier: Apache-2.0 +// nolint: thelper // for using dt *testing.T and keeping test code idiomatic. package test import ( @@ -65,50 +66,56 @@ func (c *Context) Validate() error { return nil } -func (c *Context) Deploy(t *testing.T) { +func (c *Context) Deploy(dt *testing.T) { + t := WithLog(dt, c.logger) t.Helper() if err := c.deployer.Deploy(c); err != nil { - t.Fatal(err) + t.Fatalf("Failed to deploy workload: %s", err) } } -func (c *Context) Undeploy(t *testing.T) { +func (c *Context) Undeploy(dt *testing.T) { + t := WithLog(dt, c.logger) t.Helper() if err := c.deployer.Undeploy(c); err != nil { - t.Fatal(err) + t.Fatalf("Failed to undeploy workload: %s", err) } } -func (c *Context) Enable(t *testing.T) { +func (c *Context) Enable(dt *testing.T) { + t := WithLog(dt, c.logger) t.Helper() if err := dractions.EnableProtection(c); err != nil { - t.Fatal(err) + t.Fatalf("Failed to enable protection for workload: %s", err) } } -func (c *Context) Disable(t *testing.T) { +func (c *Context) Disable(dt *testing.T) { + t := WithLog(dt, c.logger) t.Helper() if err := dractions.DisableProtection(c); err != nil { - t.Fatal(err) + t.Fatalf("Failed to disable protection for workload: %s", err) } } -func (c *Context) Failover(t *testing.T) { +func (c *Context) Failover(dt *testing.T) { + t := WithLog(dt, c.logger) t.Helper() if err := dractions.Failover(c); err != nil { - t.Fatal(err) + t.Fatalf("Failed to failover workload: %s", err) } } -func (c *Context) Relocate(t *testing.T) { +func (c *Context) Relocate(dt *testing.T) { + t := WithLog(dt, c.logger) t.Helper() if err := dractions.Relocate(c); err != nil { - t.Fatal(err) + t.Fatalf("Failed to relocate workload: %s", err) } } diff --git a/e2e/test/testing.go b/e2e/test/testing.go new file mode 100644 index 000000000..09f3a2ef0 --- /dev/null +++ b/e2e/test/testing.go @@ -0,0 +1,69 @@ +// SPDX-FileCopyrightText: The RamenDR authors +// SPDX-License-Identifier: Apache-2.0 + +package test + +import ( + "fmt" + "testing" + + "github.com/go-logr/logr" +) + +// T extends testing.T to use a custom logger. +type T struct { + *testing.T + log logr.Logger +} + +// WithLog returns a t wrapped with a specified log. +// nolint: thelper +func WithLog(t *testing.T, log logr.Logger) *T { + return &T{T: t, log: log} +} + +// Log writes a message to the log. +func (t *T) Log(msg string) { + t.log.Info(msg) +} + +// Log writes a formatted message to the log. +func (t *T) Logf(format string, args ...any) { + t.log.Info(fmt.Sprintf(format, args...)) +} + +// Error writes an error message to the log and mark the test as failed. +func (t *T) Error(msg string) { + t.log.Error(nil, msg) + t.T.Fail() +} + +// Errorf writes a formatted error message to the log and markd the test as failed. +func (t *T) Errorf(format string, args ...any) { + t.log.Error(nil, fmt.Sprintf(format, args...)) + t.T.Fail() +} + +// Fatal writes an error message to the log and fail the text immediately. +func (t *T) Fatal(msg string) { + t.log.Error(nil, msg) + t.T.FailNow() +} + +// Fatalf writes a formatted error message to the log and fail the text immediately. +func (t *T) Fatalf(format string, args ...any) { + t.log.Error(nil, fmt.Sprintf(format, args...)) + t.T.FailNow() +} + +// Skip is equivalent to Log followed by SkipNow. +func (t *T) Skip(msg string) { + t.log.Info(msg) + t.T.SkipNow() +} + +// Skipf is equivalent to Logf followed by SkipNow. +func (t *T) Skipf(format string, args ...any) { + t.log.Info(fmt.Sprintf(format, args...)) + t.T.SkipNow() +} diff --git a/e2e/validation_suite_test.go b/e2e/validation_suite_test.go index a024aa021..6ad5953a0 100644 --- a/e2e/validation_suite_test.go +++ b/e2e/validation_suite_test.go @@ -6,27 +6,35 @@ package e2e_test import ( "testing" + "github.com/ramendr/ramen/e2e/test" "github.com/ramendr/ramen/e2e/util" ) -func Validate(t *testing.T) { +func Validate(dt *testing.T) { + t := test.WithLog(dt, util.Ctx.Log) t.Helper() - t.Run("hub", func(t *testing.T) { + t.Run("hub", func(dt *testing.T) { + t := test.WithLog(dt, util.Ctx.Log) + err := util.ValidateRamenHubOperator(util.Ctx.Hub.K8sClientSet) if err != nil { - t.Fatal(err) + t.Fatalf("Failed to validated hub cluster: %s", err) } }) - t.Run("c1", func(t *testing.T) { + t.Run("c1", func(dt *testing.T) { + t := test.WithLog(dt, util.Ctx.Log) + err := util.ValidateRamenDRClusterOperator(util.Ctx.C1.K8sClientSet, "c1") if err != nil { - t.Fatal(err) + t.Fatalf("Failed to validated dr cluster c1: %s", err) } }) - t.Run("c2", func(t *testing.T) { + t.Run("c2", func(dt *testing.T) { + t := test.WithLog(dt, util.Ctx.Log) + err := util.ValidateRamenDRClusterOperator(util.Ctx.C2.K8sClientSet, "c2") if err != nil { - t.Fatal(err) + t.Fatalf("Failed to validated dr cluster c2: %s", err) } }) }