Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

e2e: log errors #1596

Open
wants to merge 2 commits into
base: main
Choose a base branch
from
Open

e2e: log errors #1596

wants to merge 2 commits into from

Conversation

nirs
Copy link
Member

@nirs nirs commented Oct 22, 2024

When a test fails, we the go test framework logs the failure in an
unhelpful way. This works for unit tests, since they are simple and do
not log anything, but our tests are complex and log a lot. The failure
logs from go test are hidden and hard to find.

This change add wrappers for t.Fatal, t.FailNow, t.Skip, and t.Skipf so
they use our logger instead of the go test framework logger. This
ensures that every failure will have a proper ERROR log which is very
easy to find. Errors logs include a traceback making it easier to
understand the failure.

When handling errors in parent tests we don't have any context and we
cannot log any useful error. The actual error that failed the sub test
already logged the error, so we just mark the test as failed with
util.FailNow().

Examples errors with this change:

2024-10-22T16:13:04.496+0530	ERROR	util/testing.go:14	Deploy failed	{"error": "exit status 1"}
github.com/ramendr/ramen/e2e/util.Fatal
	/home/github/actions-runner/_work/ramen/ramen/e2e/util/testing.go:14
github.com/ramendr/ramen/e2e_test.DeployAction
	/home/github/actions-runner/_work/ramen/ramen/e2e/actions_test.go:21
testing.tRunner
	/usr/local/go/src/testing/testing.go:1690
2024-10-22T16:15:12.286+0530	ERROR	util/testing.go:14	Failover failed	{"error": "Operation cannot be fulfilled on drplacementcontrols.ramendr.openshift.io \"subscr-deploy-cephfs-busybox\": the object has been modified; please apply your changes to the latest version and try again"}
github.com/ramendr/ramen/e2e/util.Fatal
	/home/github/actions-runner/_work/ramen/ramen/e2e/util/testing.go:14
github.com/ramendr/ramen/e2e_test.FailoverAction
	/home/github/actions-runner/_work/ramen/ramen/e2e/actions_test.go:43
testing.tRunner
	/usr/local/go/src/testing/testing.go:1690

Example build: https://github.com/RamenDR/ramen/actions/runs/11450725254/job/31880167402

Fixes #1595

Rebased on #1625 to save unneeded work.

@nirs
Copy link
Member Author

nirs commented Oct 22, 2024

Example failing build

2024-10-22T10:42:30.6592037Z /home/github/actions-runner/_work/ramen/ramen/bin/controller-gen rbac:roleName=operator-role crd:generateEmbeddedObjectMeta=true webhook paths="./..." output:crd:artifacts:config=config/crd/bases
2024-10-22T10:42:33.8177162Z cd e2e && ./e2e-rdr.sh
2024-10-22T10:42:33.8228001Z Running tests...
2024-10-22T10:42:36.1691614Z 2024-10-22T16:12:36.168+0530	INFO	util/config.go:48	No configuration file specified, using default value config.yaml
2024-10-22T10:42:36.1769885Z 2024-10-22T16:12:36.176+0530	INFO	e2e/main_test.go:41	Global setting	{"Timeout": 600}
2024-10-22T10:42:36.1772829Z 2024-10-22T16:12:36.176+0530	INFO	e2e/main_test.go:42	Global setting	{"Retry Interval": 30}
2024-10-22T10:42:36.1774111Z === RUN   TestSuites
2024-10-22T10:42:36.1775122Z 2024-10-22T16:12:36.176+0530	INFO	e2e/main_test.go:57	TestSuites
2024-10-22T10:42:36.1775903Z === RUN   TestSuites/Validate
2024-10-22T10:42:36.1777154Z === RUN   TestSuites/Validate/hub
2024-10-22T10:42:36.1778720Z 2024-10-22T16:12:36.176+0530	INFO	e2e/validation_suite_test.go:37	Validating hub cluster	{"name": "hub"}
2024-10-22T10:42:36.2185659Z 2024-10-22T16:12:36.217+0530	INFO	e2e/validation_suite_test.go:48	Ramen hub operator is running	{"pod": "ramen-hub-operator-84d7dc89bd-6lbgf"}
2024-10-22T10:42:36.2186916Z === RUN   TestSuites/Validate/c1
2024-10-22T10:42:36.2188001Z 2024-10-22T16:12:36.218+0530	INFO	e2e/validation_suite_test.go:54	Validating managed cluster	{"name": "c1"}
2024-10-22T10:42:36.3371626Z 2024-10-22T16:12:36.336+0530	INFO	e2e/validation_suite_test.go:65	Ramen DR cluster operator is running	{"pod": "ramen-dr-cluster-operator-896d8c9f6-pswx9"}
2024-10-22T10:42:36.3373264Z === RUN   TestSuites/Validate/c2
2024-10-22T10:42:36.3374322Z 2024-10-22T16:12:36.336+0530	INFO	e2e/validation_suite_test.go:54	Validating managed cluster	{"name": "c2"}
2024-10-22T10:42:36.3564993Z 2024-10-22T16:12:36.355+0530	INFO	e2e/validation_suite_test.go:65	Ramen DR cluster operator is running	{"pod": "ramen-dr-cluster-operator-896d8c9f6-pswx9"}
2024-10-22T10:42:36.3566357Z === RUN   TestSuites/Exhaustive
2024-10-22T10:42:36.3566854Z === PAUSE TestSuites/Exhaustive
2024-10-22T10:42:36.3567359Z === CONT  TestSuites/Exhaustive
2024-10-22T10:42:36.3939764Z 2024-10-22T16:12:36.393+0530	INFO	util/crud.go:77	channel ramen-gitops is created
2024-10-22T10:42:36.3941745Z === RUN   TestSuites/Exhaustive/Deploy-cephfs
2024-10-22T10:42:36.3943915Z === PAUSE TestSuites/Exhaustive/Deploy-cephfs
2024-10-22T10:42:36.3945198Z === RUN   TestSuites/Exhaustive/Deploy-cephfs#01
2024-10-22T10:42:36.3946126Z === PAUSE TestSuites/Exhaustive/Deploy-cephfs#01
2024-10-22T10:42:36.3946831Z === RUN   TestSuites/Exhaustive/Deploy-cephfs#02
2024-10-22T10:42:36.3952721Z === PAUSE TestSuites/Exhaustive/Deploy-cephfs#02
2024-10-22T10:42:36.3953906Z === RUN   TestSuites/Exhaustive/Deploy-rbd
2024-10-22T10:42:36.3954553Z === PAUSE TestSuites/Exhaustive/Deploy-rbd
2024-10-22T10:42:36.3955252Z === RUN   TestSuites/Exhaustive/Deploy-rbd#01
2024-10-22T10:42:36.3955953Z === PAUSE TestSuites/Exhaustive/Deploy-rbd#01
2024-10-22T10:42:36.3956639Z === RUN   TestSuites/Exhaustive/Deploy-rbd#02
2024-10-22T10:42:36.3957327Z === PAUSE TestSuites/Exhaustive/Deploy-rbd#02
2024-10-22T10:42:36.3964063Z === CONT  TestSuites/Exhaustive/Deploy-cephfs
2024-10-22T10:42:36.3966563Z === RUN   TestSuites/Exhaustive/Deploy-cephfs/Subscr
2024-10-22T10:42:36.3968103Z === CONT  TestSuites/Exhaustive/Deploy-rbd#01
2024-10-22T10:42:36.3969831Z === CONT  TestSuites/Exhaustive/Deploy-cephfs#02
2024-10-22T10:42:36.3971501Z === RUN   TestSuites/Exhaustive/Deploy-cephfs#02/Disapp
2024-10-22T10:42:36.3973258Z === PAUSE TestSuites/Exhaustive/Deploy-cephfs#02/Disapp
2024-10-22T10:42:36.3974879Z === CONT  TestSuites/Exhaustive/Deploy-cephfs#02/Disapp
2024-10-22T10:42:36.3977263Z 2024-10-22T16:12:36.394+0530	INFO	util/testing.go:32	Workload Deploy-cephfs not supported by deployer Disapp
2024-10-22T10:42:36.3979609Z === PAUSE TestSuites/Exhaustive/Deploy-cephfs/Subscr
2024-10-22T10:42:36.3981047Z === CONT  TestSuites/Exhaustive/Deploy-cephfs/Subscr
2024-10-22T10:42:36.3982701Z === RUN   TestSuites/Exhaustive/Deploy-rbd#01/Appset
2024-10-22T10:42:36.3984669Z === RUN   TestSuites/Exhaustive/Deploy-cephfs/Subscr/Deploy
2024-10-22T10:42:36.3986658Z === PAUSE TestSuites/Exhaustive/Deploy-rbd#01/Appset
2024-10-22T10:42:36.3988350Z === CONT  TestSuites/Exhaustive/Deploy-rbd#01/Appset
2024-10-22T10:42:36.3990104Z === CONT  TestSuites/Exhaustive/Deploy-rbd#02
2024-10-22T10:42:36.3992543Z 2024-10-22T16:12:36.394+0530	INFO	deployers/subscription.go:31	enter Deploy subscr-deploy-cephfs-busybox
2024-10-22T10:42:36.3995372Z === RUN   TestSuites/Exhaustive/Deploy-rbd#02/Disapp
2024-10-22T10:42:36.3996871Z === PAUSE TestSuites/Exhaustive/Deploy-rbd#02/Disapp
2024-10-22T10:42:36.3998481Z === CONT  TestSuites/Exhaustive/Deploy-rbd#02/Disapp
2024-10-22T10:42:36.4000540Z === RUN   TestSuites/Exhaustive/Deploy-rbd#02/Disapp/Deploy
2024-10-22T10:42:36.4002881Z === CONT  TestSuites/Exhaustive/Deploy-rbd
2024-10-22T10:42:36.4005755Z 2024-10-22T16:12:36.394+0530	INFO	deployers/discoveredapps.go:24	enter Deploy disapp-deploy-rbd-busybox
2024-10-22T10:42:36.4007905Z === RUN   TestSuites/Exhaustive/Deploy-rbd/Subscr
2024-10-22T10:42:36.4009594Z === PAUSE TestSuites/Exhaustive/Deploy-rbd/Subscr
2024-10-22T10:42:36.4011101Z === CONT  TestSuites/Exhaustive/Deploy-rbd/Subscr
2024-10-22T10:42:36.4012880Z === CONT  TestSuites/Exhaustive/Deploy-cephfs#01
2024-10-22T10:42:36.4014688Z === RUN   TestSuites/Exhaustive/Deploy-rbd#01/Appset/Deploy
2024-10-22T10:42:36.4016349Z === RUN   TestSuites/Exhaustive/Deploy-cephfs#01/Appset
2024-10-22T10:42:36.4017990Z === PAUSE TestSuites/Exhaustive/Deploy-cephfs#01/Appset
2024-10-22T10:42:36.4019608Z === CONT  TestSuites/Exhaustive/Deploy-cephfs#01/Appset
2024-10-22T10:42:36.4021292Z === RUN   TestSuites/Exhaustive/Deploy-cephfs#01/Appset/Deploy
2024-10-22T10:42:36.4024902Z 2024-10-22T16:12:36.394+0530	INFO	deployers/applicationset.go:17	enter Deploy appset-deploy-cephfs-busybox
2024-10-22T10:42:36.4027989Z === RUN   TestSuites/Exhaustive/Deploy-rbd/Subscr/Deploy
2024-10-22T10:42:36.4031253Z 2024-10-22T16:12:36.394+0530	INFO	deployers/applicationset.go:17	enter Deploy appset-deploy-rbd-busybox
2024-10-22T10:42:36.4035199Z 2024-10-22T16:12:36.395+0530	INFO	deployers/subscription.go:31	enter Deploy subscr-deploy-rbd-busybox
2024-10-22T10:42:36.7976760Z === RUN   TestSuites/Exhaustive/Deploy-rbd#01/Appset/Enable
2024-10-22T10:42:36.7978946Z 2024-10-22T16:12:36.797+0530	INFO	dractions/actions.go:38	enter EnableProtection appset-deploy-rbd-busybox
2024-10-22T10:42:36.8411655Z === RUN   TestSuites/Exhaustive/Deploy-cephfs#01/Appset/Enable
2024-10-22T10:42:36.8413154Z 2024-10-22T16:12:36.840+0530	INFO	dractions/actions.go:38	enter EnableProtection appset-deploy-cephfs-busybox
2024-10-22T10:42:41.7478773Z 2024-10-22T16:12:41.747+0530	INFO	deployers/retry.go:32	subscription subscr-deploy-cephfs-busybox phase is Propagated
2024-10-22T10:42:41.7489678Z === RUN   TestSuites/Exhaustive/Deploy-cephfs/Subscr/Enable
2024-10-22T10:42:41.7491700Z 2024-10-22T16:12:41.747+0530	INFO	dractions/actions.go:38	enter EnableProtection subscr-deploy-cephfs-busybox
2024-10-22T10:42:41.7627477Z 2024-10-22T16:12:41.762+0530	INFO	dractions/actions.go:56	got clusterName rdr-dr1 from subscr-deploy-cephfs-busybox-decision-1
2024-10-22T10:42:41.7632148Z 2024-10-22T16:12:41.762+0530	INFO	dractions/actions.go:67	update placement subscr-deploy-cephfs-busybox annotation
2024-10-22T10:42:41.7874522Z 2024-10-22T16:12:41.786+0530	INFO	dractions/actions.go:73	create drpc subscr-deploy-cephfs-busybox
2024-10-22T10:43:04.4967658Z 2024-10-22T16:13:04.496+0530	INFO	deployers/discoveredapps.go:53	
2024-10-22T10:43:04.4969442Z 2024-10-22T16:13:04.496+0530	ERROR	util/testing.go:14	Deploy failed	{"error": "exit status 1"}
2024-10-22T10:43:04.4970425Z github.com/ramendr/ramen/e2e/util.Fatal
2024-10-22T10:43:04.4971265Z 	/home/github/actions-runner/_work/ramen/ramen/e2e/util/testing.go:14
2024-10-22T10:43:04.4972041Z github.com/ramendr/ramen/e2e_test.DeployAction
2024-10-22T10:43:04.4981272Z 	/home/github/actions-runner/_work/ramen/ramen/e2e/actions_test.go:21
2024-10-22T10:43:04.4982110Z testing.tRunner
2024-10-22T10:43:04.4982919Z 	/usr/local/go/src/testing/testing.go:1690
2024-10-22T10:43:06.8588988Z 2024-10-22T16:13:06.857+0530	INFO	dractions/actions.go:56	got clusterName rdr-dr1 from appset-deploy-rbd-busybox-decision-1
2024-10-22T10:43:06.8594718Z 2024-10-22T16:13:06.857+0530	INFO	dractions/actions.go:67	update placement appset-deploy-rbd-busybox annotation
2024-10-22T10:43:06.8728647Z 2024-10-22T16:13:06.872+0530	INFO	dractions/actions.go:73	create drpc appset-deploy-rbd-busybox
2024-10-22T10:43:06.8837343Z 2024-10-22T16:13:06.882+0530	INFO	dractions/actions.go:56	got clusterName rdr-dr2 from appset-deploy-cephfs-busybox-decision-1
2024-10-22T10:43:06.8846334Z 2024-10-22T16:13:06.882+0530	INFO	dractions/actions.go:67	update placement appset-deploy-cephfs-busybox annotation
2024-10-22T10:43:06.9013321Z 2024-10-22T16:13:06.900+0530	INFO	dractions/actions.go:73	create drpc appset-deploy-cephfs-busybox
2024-10-22T10:43:11.7780346Z 2024-10-22T16:13:11.777+0530	INFO	deployers/retry.go:32	subscription subscr-deploy-rbd-busybox phase is Propagated
2024-10-22T10:43:11.7782663Z === RUN   TestSuites/Exhaustive/Deploy-rbd/Subscr/Enable
2024-10-22T10:43:11.7784478Z 2024-10-22T16:13:11.777+0530	INFO	dractions/actions.go:38	enter EnableProtection subscr-deploy-rbd-busybox
2024-10-22T10:43:11.7866182Z 2024-10-22T16:13:11.786+0530	INFO	dractions/actions.go:56	got clusterName rdr-dr2 from subscr-deploy-rbd-busybox-decision-1
2024-10-22T10:43:11.7868754Z 2024-10-22T16:13:11.786+0530	INFO	dractions/actions.go:67	update placement subscr-deploy-rbd-busybox annotation
2024-10-22T10:43:11.7999041Z 2024-10-22T16:13:11.799+0530	INFO	dractions/actions.go:73	create drpc subscr-deploy-rbd-busybox
2024-10-22T10:45:07.1537765Z 2024-10-22T16:15:07.152+0530	INFO	dractions/retry.go:67	drpc appset-deploy-rbd-busybox is ready
2024-10-22T10:45:07.1541520Z === RUN   TestSuites/Exhaustive/Deploy-rbd#01/Appset/Failover
2024-10-22T10:45:07.1545454Z 2024-10-22T16:15:07.153+0530	INFO	dractions/actions.go:115	enter Failover appset-deploy-rbd-busybox
2024-10-22T10:45:07.1684497Z 2024-10-22T16:15:07.167+0530	INFO	dractions/retry.go:67	drpc appset-deploy-rbd-busybox is ready
2024-10-22T10:45:07.2076862Z 2024-10-22T16:15:07.206+0530	INFO	dractions/actions.go:187	update drpc appset-deploy-rbd-busybox failover to rdr-dr2
2024-10-22T10:45:11.9624617Z 2024-10-22T16:15:11.961+0530	INFO	dractions/retry.go:67	drpc subscr-deploy-rbd-busybox is ready
2024-10-22T10:45:11.9625768Z === RUN   TestSuites/Exhaustive/Deploy-rbd/Subscr/Failover
2024-10-22T10:45:11.9626909Z 2024-10-22T16:15:11.961+0530	INFO	dractions/actions.go:115	enter Failover subscr-deploy-rbd-busybox
2024-10-22T10:45:11.9923214Z 2024-10-22T16:15:11.991+0530	INFO	dractions/retry.go:67	drpc subscr-deploy-cephfs-busybox is ready
2024-10-22T10:45:11.9926793Z === RUN   TestSuites/Exhaustive/Deploy-cephfs/Subscr/Failover
2024-10-22T10:45:11.9930450Z 2024-10-22T16:15:11.991+0530	INFO	dractions/actions.go:115	enter Failover subscr-deploy-cephfs-busybox
2024-10-22T10:45:12.0049686Z 2024-10-22T16:15:12.004+0530	INFO	dractions/retry.go:67	drpc subscr-deploy-rbd-busybox is ready
2024-10-22T10:45:12.0448265Z 2024-10-22T16:15:12.043+0530	INFO	dractions/retry.go:67	drpc subscr-deploy-cephfs-busybox is ready
2024-10-22T10:45:12.2072717Z 2024-10-22T16:15:12.206+0530	INFO	dractions/actions.go:187	update drpc subscr-deploy-rbd-busybox failover to rdr-dr1
2024-10-22T10:45:12.2258896Z 2024-10-22T16:15:12.224+0530	INFO	dractions/actions.go:187	update drpc subscr-deploy-cephfs-busybox failover to rdr-dr2
2024-10-22T10:45:12.2876457Z 2024-10-22T16:15:12.286+0530	ERROR	util/testing.go:14	Failover failed	{"error": "Operation cannot be fulfilled on drplacementcontrols.ramendr.openshift.io \"subscr-deploy-cephfs-busybox\": the object has been modified; please apply your changes to the latest version and try again"}
2024-10-22T10:45:12.2879303Z github.com/ramendr/ramen/e2e/util.Fatal
2024-10-22T10:45:12.2880311Z 	/home/github/actions-runner/_work/ramen/ramen/e2e/util/testing.go:14
2024-10-22T10:45:12.2881223Z github.com/ramendr/ramen/e2e_test.FailoverAction
2024-10-22T10:45:12.2882371Z 	/home/github/actions-runner/_work/ramen/ramen/e2e/actions_test.go:43
2024-10-22T10:45:12.2883163Z testing.tRunner
2024-10-22T10:45:12.2883687Z 	/usr/local/go/src/testing/testing.go:1690
2024-10-22T10:45:37.2022150Z 2024-10-22T16:15:37.201+0530	INFO	dractions/retry.go:67	drpc appset-deploy-cephfs-busybox is ready
2024-10-22T10:45:37.2029851Z === RUN   TestSuites/Exhaustive/Deploy-cephfs#01/Appset/Failover
2024-10-22T10:45:37.2031142Z 2024-10-22T16:15:37.201+0530	INFO	dractions/actions.go:115	enter Failover appset-deploy-cephfs-busybox
2024-10-22T10:45:37.2744550Z 2024-10-22T16:15:37.273+0530	INFO	dractions/retry.go:67	drpc appset-deploy-cephfs-busybox is ready
2024-10-22T10:45:37.4332032Z 2024-10-22T16:15:37.432+0530	INFO	dractions/actions.go:187	update drpc appset-deploy-cephfs-busybox failover to rdr-dr1
2024-10-22T10:45:42.4631783Z 2024-10-22T16:15:42.462+0530	INFO	dractions/retry.go:124	drpc appset-deploy-rbd-busybox phase is FailedOver
2024-10-22T10:45:47.3130774Z 2024-10-22T16:15:47.312+0530	INFO	dractions/retry.go:124	drpc subscr-deploy-rbd-busybox phase is FailedOver
2024-10-22T10:46:12.6641124Z 2024-10-22T16:16:12.663+0530	INFO	dractions/retry.go:124	drpc appset-deploy-cephfs-busybox phase is FailedOver
2024-10-22T10:48:12.7059646Z 2024-10-22T16:18:12.705+0530	INFO	dractions/retry.go:67	drpc appset-deploy-rbd-busybox is ready
2024-10-22T10:48:12.7069135Z === RUN   TestSuites/Exhaustive/Deploy-rbd#01/Appset/Relocate
2024-10-22T10:48:12.7073355Z 2024-10-22T16:18:12.705+0530	INFO	dractions/actions.go:130	enter Relocate appset-deploy-rbd-busybox
2024-10-22T10:48:12.7180439Z 2024-10-22T16:18:12.717+0530	INFO	dractions/retry.go:67	drpc appset-deploy-rbd-busybox is ready
2024-10-22T10:48:13.0365191Z 2024-10-22T16:18:13.035+0530	INFO	dractions/actions.go:187	update drpc appset-deploy-rbd-busybox relocate to rdr-dr1
2024-10-22T10:48:47.4121260Z 2024-10-22T16:18:47.411+0530	INFO	dractions/retry.go:67	drpc subscr-deploy-rbd-busybox is ready
2024-10-22T10:48:47.4122808Z === RUN   TestSuites/Exhaustive/Deploy-rbd/Subscr/Relocate
2024-10-22T10:48:47.4128726Z 2024-10-22T16:18:47.411+0530	INFO	dractions/actions.go:130	enter Relocate subscr-deploy-rbd-busybox
2024-10-22T10:48:47.4200597Z 2024-10-22T16:18:47.419+0530	INFO	dractions/retry.go:67	drpc subscr-deploy-rbd-busybox is ready
2024-10-22T10:48:47.4407486Z 2024-10-22T16:18:47.439+0530	INFO	dractions/actions.go:187	update drpc subscr-deploy-rbd-busybox relocate to rdr-dr2
2024-10-22T10:50:12.8566557Z 2024-10-22T16:20:12.856+0530	INFO	dractions/retry.go:67	drpc appset-deploy-cephfs-busybox is ready
2024-10-22T10:50:12.8573318Z === RUN   TestSuites/Exhaustive/Deploy-cephfs#01/Appset/Relocate
2024-10-22T10:50:12.8574623Z 2024-10-22T16:20:12.856+0530	INFO	dractions/actions.go:130	enter Relocate appset-deploy-cephfs-busybox
2024-10-22T10:50:12.8620058Z 2024-10-22T16:20:12.861+0530	INFO	dractions/retry.go:67	drpc appset-deploy-cephfs-busybox is ready
2024-10-22T10:50:12.8839079Z 2024-10-22T16:20:12.883+0530	INFO	dractions/actions.go:187	update drpc appset-deploy-cephfs-busybox relocate to rdr-dr2
2024-10-22T10:50:18.1939811Z 2024-10-22T16:20:18.193+0530	INFO	dractions/retry.go:124	drpc appset-deploy-rbd-busybox phase is Relocated
2024-10-22T10:50:48.2078769Z 2024-10-22T16:20:48.206+0530	INFO	dractions/retry.go:67	drpc appset-deploy-rbd-busybox is ready
2024-10-22T10:50:48.2083035Z === RUN   TestSuites/Exhaustive/Deploy-rbd#01/Appset/Disable
2024-10-22T10:50:48.2088164Z 2024-10-22T16:20:48.206+0530	INFO	dractions/actions.go:99	enter DisableProtection appset-deploy-rbd-busybox
2024-10-22T10:50:48.2092882Z 2024-10-22T16:20:48.206+0530	INFO	dractions/actions.go:104	delete drpc appset-deploy-rbd-busybox
2024-10-22T10:50:52.5120682Z 2024-10-22T16:20:52.511+0530	INFO	dractions/retry.go:124	drpc subscr-deploy-rbd-busybox phase is Relocated
2024-10-22T10:51:22.6614808Z 2024-10-22T16:21:22.660+0530	INFO	dractions/retry.go:67	drpc subscr-deploy-rbd-busybox is ready
2024-10-22T10:51:22.6616781Z === RUN   TestSuites/Exhaustive/Deploy-rbd/Subscr/Disable
2024-10-22T10:51:22.6618905Z 2024-10-22T16:21:22.660+0530	INFO	dractions/actions.go:99	enter DisableProtection subscr-deploy-rbd-busybox
2024-10-22T10:51:22.6621546Z 2024-10-22T16:21:22.660+0530	INFO	dractions/actions.go:104	delete drpc subscr-deploy-rbd-busybox
2024-10-22T10:51:23.2718822Z 2024-10-22T16:21:23.271+0530	INFO	dractions/retry.go:200	drpc appset-deploy-rbd-busybox is deleted
2024-10-22T10:51:23.2722785Z === RUN   TestSuites/Exhaustive/Deploy-rbd#01/Appset/Undeploy
2024-10-22T10:51:23.2726529Z 2024-10-22T16:21:23.271+0530	INFO	deployers/applicationset.go:46	enter Undeploy appset-deploy-rbd-busybox
2024-10-22T10:51:57.7465520Z 2024-10-22T16:21:57.745+0530	INFO	dractions/retry.go:200	drpc subscr-deploy-rbd-busybox is deleted
2024-10-22T10:51:57.7466937Z === RUN   TestSuites/Exhaustive/Deploy-rbd/Subscr/Undeploy
2024-10-22T10:51:57.7468366Z 2024-10-22T16:21:57.746+0530	INFO	deployers/subscription.go:62	enter Undeploy subscr-deploy-rbd-busybox
2024-10-22T10:53:48.0825171Z 2024-10-22T16:23:48.081+0530	INFO	dractions/retry.go:124	drpc appset-deploy-cephfs-busybox phase is Relocated
2024-10-22T10:54:18.1468397Z 2024-10-22T16:24:18.146+0530	INFO	dractions/retry.go:67	drpc appset-deploy-cephfs-busybox is ready
2024-10-22T10:54:18.1472925Z === RUN   TestSuites/Exhaustive/Deploy-cephfs#01/Appset/Disable
2024-10-22T10:54:18.1474502Z 2024-10-22T16:24:18.146+0530	INFO	dractions/actions.go:99	enter DisableProtection appset-deploy-cephfs-busybox
2024-10-22T10:54:18.1475990Z 2024-10-22T16:24:18.146+0530	INFO	dractions/actions.go:104	delete drpc appset-deploy-cephfs-busybox
2024-10-22T10:54:53.3004952Z 2024-10-22T16:24:53.299+0530	INFO	dractions/retry.go:200	drpc appset-deploy-cephfs-busybox is deleted
2024-10-22T10:54:53.3013351Z === RUN   TestSuites/Exhaustive/Deploy-cephfs#01/Appset/Undeploy
2024-10-22T10:54:53.3017855Z 2024-10-22T16:24:53.300+0530	INFO	deployers/applicationset.go:46	enter Undeploy appset-deploy-cephfs-busybox
2024-10-22T10:54:53.4037402Z 2024-10-22T16:24:53.402+0530	INFO	util/crud.go:99	channel ramen-gitops is deleted
2024-10-22T10:54:53.4433144Z --- FAIL: TestSuites (0.18s)
2024-10-22T10:54:53.4435075Z     --- PASS: TestSuites/Validate (0.18s)
2024-10-22T10:54:53.4437691Z         --- PASS: TestSuites/Validate/hub (0.04s)
2024-10-22T10:54:53.4441321Z         --- PASS: TestSuites/Validate/c1 (0.12s)
2024-10-22T10:54:53.4445316Z         --- PASS: TestSuites/Validate/c2 (0.02s)
2024-10-22T10:54:53.4447331Z     --- FAIL: TestSuites/Exhaustive (0.11s)
2024-10-22T10:54:53.4449693Z         --- PASS: TestSuites/Exhaustive/Deploy-cephfs#02 (0.00s)
2024-10-22T10:54:53.4452909Z             --- SKIP: TestSuites/Exhaustive/Deploy-cephfs#02/Disapp (0.00s)
2024-10-22T10:54:53.4455692Z         --- FAIL: TestSuites/Exhaustive/Deploy-rbd#02 (0.00s)
2024-10-22T10:54:53.4459073Z             --- FAIL: TestSuites/Exhaustive/Deploy-rbd#02/Disapp (28.10s)
2024-10-22T10:54:53.4462136Z                 --- FAIL: TestSuites/Exhaustive/Deploy-rbd#02/Disapp/Deploy (28.10s)
2024-10-22T10:54:53.4465576Z         --- FAIL: TestSuites/Exhaustive/Deploy-cephfs (0.00s)
2024-10-22T10:54:53.4468298Z             --- FAIL: TestSuites/Exhaustive/Deploy-cephfs/Subscr (155.89s)
2024-10-22T10:54:53.4472779Z                 --- PASS: TestSuites/Exhaustive/Deploy-cephfs/Subscr/Deploy (5.35s)
2024-10-22T10:54:53.4476119Z                 --- PASS: TestSuites/Exhaustive/Deploy-cephfs/Subscr/Enable (150.24s)
2024-10-22T10:54:53.4479263Z                 --- FAIL: TestSuites/Exhaustive/Deploy-cephfs/Subscr/Failover (0.30s)
2024-10-22T10:54:53.4482789Z         --- PASS: TestSuites/Exhaustive/Deploy-rbd#01 (0.00s)
2024-10-22T10:54:53.4486363Z             --- PASS: TestSuites/Exhaustive/Deploy-rbd#01/Appset (527.40s)
2024-10-22T10:54:53.4490287Z                 --- PASS: TestSuites/Exhaustive/Deploy-rbd#01/Appset/Deploy (0.40s)
2024-10-22T10:54:53.4494424Z                 --- PASS: TestSuites/Exhaustive/Deploy-rbd#01/Appset/Enable (150.36s)
2024-10-22T10:54:53.4499711Z                 --- PASS: TestSuites/Exhaustive/Deploy-rbd#01/Appset/Failover (185.55s)
2024-10-22T10:54:53.4505193Z                 --- PASS: TestSuites/Exhaustive/Deploy-rbd#01/Appset/Relocate (155.50s)
2024-10-22T10:54:53.4509535Z                 --- PASS: TestSuites/Exhaustive/Deploy-rbd#01/Appset/Disable (35.06s)
2024-10-22T10:54:53.4515305Z                 --- PASS: TestSuites/Exhaustive/Deploy-rbd#01/Appset/Undeploy (0.52s)
2024-10-22T10:54:53.4538657Z         --- PASS: TestSuites/Exhaustive/Deploy-rbd (0.00s)
2024-10-22T10:54:53.4539951Z             --- PASS: TestSuites/Exhaustive/Deploy-rbd/Subscr (561.53s)
2024-10-22T10:54:53.4541026Z                 --- PASS: TestSuites/Exhaustive/Deploy-rbd/Subscr/Deploy (35.38s)
2024-10-22T10:54:53.4542165Z                 --- PASS: TestSuites/Exhaustive/Deploy-rbd/Subscr/Enable (120.18s)
2024-10-22T10:54:53.4543476Z                 --- PASS: TestSuites/Exhaustive/Deploy-rbd/Subscr/Failover (215.45s)
2024-10-22T10:54:53.4544616Z                 --- PASS: TestSuites/Exhaustive/Deploy-rbd/Subscr/Relocate (155.25s)
2024-10-22T10:54:53.4545747Z                 --- PASS: TestSuites/Exhaustive/Deploy-rbd/Subscr/Disable (35.09s)
2024-10-22T10:54:53.4546859Z                 --- PASS: TestSuites/Exhaustive/Deploy-rbd/Subscr/Undeploy (0.18s)
2024-10-22T10:54:53.4547896Z         --- PASS: TestSuites/Exhaustive/Deploy-cephfs#01 (0.00s)
2024-10-22T10:54:53.4548916Z             --- PASS: TestSuites/Exhaustive/Deploy-cephfs#01/Appset (736.97s)
2024-10-22T10:54:53.4550058Z                 --- PASS: TestSuites/Exhaustive/Deploy-cephfs#01/Appset/Deploy (0.45s)
2024-10-22T10:54:53.4551258Z                 --- PASS: TestSuites/Exhaustive/Deploy-cephfs#01/Appset/Enable (180.36s)
2024-10-22T10:54:53.4552752Z                 --- PASS: TestSuites/Exhaustive/Deploy-cephfs#01/Appset/Failover (275.65s)
2024-10-22T10:54:53.4554017Z                 --- PASS: TestSuites/Exhaustive/Deploy-cephfs#01/Appset/Relocate (245.29s)
2024-10-22T10:54:53.4555251Z                 --- PASS: TestSuites/Exhaustive/Deploy-cephfs#01/Appset/Disable (35.15s)
2024-10-22T10:54:53.4556443Z                 --- PASS: TestSuites/Exhaustive/Deploy-cephfs#01/Appset/Undeploy (0.07s)
2024-10-22T10:54:53.4557230Z FAIL
2024-10-22T10:54:53.4557576Z exit status 1
2024-10-22T10:54:53.4558026Z FAIL	github.com/ramendr/ramen/e2e	737.315s

Simplify the tests by moving the validation code into the util package.

util.ValidateRamenHubOperator() and util.ValidateDRClusterOperator()
returns now and error if ramen operator is not in valid state, and nil
if the operator is in good state. They also log information about the
pod.

Separate looking up the ramen operator pod, and checking for its status.
This way when the pod is not running we return an error with more
context (e.g pod name, pod phase).

Tests are using sub tests to have one test per cluster, which makes test
output more clear.

We use the virtual cluster names ("c1", "c2"). This can be improved
later by getting the cluster names from the dr policy, the clusterset,
or the environment file.

Example run - ramen not deployed:

    % go test -run TestSuites/Validate --config ../e2e.yaml
    2024-10-29T19:32:09.522+0200	INFO	e2e/main_test.go:41	Global setting	{"Timeout": 600}
    2024-10-29T19:32:09.523+0200	INFO	e2e/main_test.go:42	Global setting	{"Retry Interval": 30}
    2024-10-29T19:32:09.523+0200	INFO	e2e/main_test.go:57	TestSuites
    --- FAIL: TestSuites (0.06s)
        --- FAIL: TestSuites/Validate (0.06s)
            --- FAIL: TestSuites/Validate/hub (0.03s)
                validation_suite_test.go:17: no pod with label selector "app=ramen-hub" and identifier "ramen-hub-operator" in namespace "ramen-system"
            --- FAIL: TestSuites/Validate/c1 (0.02s)
                validation_suite_test.go:23: no pod with label selector "app=ramen-dr-cluster" and identifier "ramen-dr-cluster-operator" in namespace "ramen-system"
            --- FAIL: TestSuites/Validate/c2 (0.02s)
                validation_suite_test.go:29: no pod with label selector "app=ramen-dr-cluster" and identifier "ramen-dr-cluster-operator" in namespace "ramen-system"
        main_test.go:60: failed to validate the test suite
    FAIL
    exit status 1
    FAIL	github.com/ramendr/ramen/e2e	0.683s

Example run - ramen deployed:

    % go test -run TestSuites/Validate --config ../e2e.yaml
    2024-10-29T19:43:51.899+0200	INFO	e2e/main_test.go:41	Global setting	{"Timeout": 600}
    2024-10-29T19:43:51.900+0200	INFO	e2e/main_test.go:42	Global setting	{"Retry Interval": 30}
    2024-10-29T19:43:51.901+0200	INFO	e2e/main_test.go:57	TestSuites
    2024-10-29T19:43:51.932+0200	INFO	util/validation.go:35	Ramen hub operator is running	{"pod": "ramen-hub-operator-659658dfcf-c2xnj"}
    2024-10-29T19:43:51.951+0200	INFO	util/validation.go:59	Ramen dr cluster operator is running	{"cluster": "c1", "pod": "ramen-dr-cluster-operator-74f89d85d7-nwx54"}
    2024-10-29T19:43:51.970+0200	INFO	util/validation.go:59	Ramen dr cluster operator is running	{"cluster": "c2", "pod": "ramen-dr-cluster-operator-74f89d85d7-6gjhs"}
    PASS
    ok  	github.com/ramendr/ramen/e2e	0.759s

Signed-off-by: Nir Soffer <[email protected]>
@nirs nirs force-pushed the e2e-logs branch 2 times, most recently from be2abe1 to 2bd2ced Compare October 30, 2024 14:05
@nirs nirs changed the title WIP: Improve e2e logging Improve e2e logging Oct 30, 2024
When a test fails, we the go test framework logs the failure in an
unhelpful way. This works for unit tests, since they are simple and do
not log anything, but our tests are complex and log a lot. The failure
logs from go test are hidden and hard to find.

This change add wrappers for t.Fatal, t.FailNow, t.Skip, and t.Skipf so
they use our logger instead of the go test framework logger. This
ensures that every failure will have a proper ERROR log which is very
easy to find. Errors logs include a traceback making it easier to
understand the failure.

When handling errors in parent tests we don't have any context and we
cannot log any useful error. The actual error that failed the sub test
already logged the error, so we just mark the test as failed with
util.FailNow().

Fixes: RamenDR#1595
Signed-off-by: Nir Soffer <[email protected]>
@nirs nirs marked this pull request as ready for review October 30, 2024 14:12
@nirs nirs changed the title Improve e2e logging e2e: log errors Oct 30, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

e2e logging: Hard to find errors in test log
1 participant