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: Easier to follow log #1628

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

e2e: Easier to follow log #1628

wants to merge 4 commits into from

Conversation

nirs
Copy link
Member

@nirs nirs commented Oct 30, 2024

Replace the unhelpful file:line part with the name of the test (workload-deployer-appname) and clean up the logging message.

Fixes #1597

@nirs
Copy link
Member Author

nirs commented Oct 30, 2024

Example run

% ./run.sh --config ../e2e.yaml
Running tests...
2024-10-31T19:39:06.164+0200	INFO	Global setting	{"Timeout": "10m0s"}
2024-10-31T19:39:06.164+0200	INFO	Global setting	{"Retry Interval": "5s"}
=== RUN   TestSuites
2024-10-31T19:39:06.164+0200	INFO	TestSuites
=== RUN   TestSuites/Validate
=== RUN   TestSuites/Validate/CheckRamenHubOperatorStatus
2024-10-31T19:39:06.164+0200	INFO	enter CheckRamenHubOperatorStatus
2024-10-31T19:39:06.189+0200	INFO	Ramen Hub Operator is running	{"pod": "ramen-hub-operator-659658dfcf-bsqpt"}
=== RUN   TestSuites/Validate/CheckRamenSpokeOperatorStatus
2024-10-31T19:39:06.189+0200	INFO	enter CheckRamenSpokeOperatorStatus
2024-10-31T19:39:06.206+0200	INFO	Ramen Spoke Operator is running on cluster 1	{"pod": "ramen-dr-cluster-operator-74f89d85d7-jpqc7"}
2024-10-31T19:39:06.222+0200	INFO	Ramen Spoke Operator is running on cluster 2	{"pod": "ramen-dr-cluster-operator-74f89d85d7-ddh45"}
=== RUN   TestSuites/Exhaustive
=== PAUSE TestSuites/Exhaustive
=== CONT  TestSuites/Exhaustive
2024-10-31T19:39:06.238+0200	INFO	Created channel ramen-gitops
=== RUN   TestSuites/Exhaustive/cephfs
=== PAUSE TestSuites/Exhaustive/cephfs
=== RUN   TestSuites/Exhaustive/cephfs#01
=== PAUSE TestSuites/Exhaustive/cephfs#01
=== RUN   TestSuites/Exhaustive/cephfs#02
=== PAUSE TestSuites/Exhaustive/cephfs#02
=== RUN   TestSuites/Exhaustive/rbd
=== PAUSE TestSuites/Exhaustive/rbd
=== RUN   TestSuites/Exhaustive/rbd#01
=== PAUSE TestSuites/Exhaustive/rbd#01
=== RUN   TestSuites/Exhaustive/rbd#02
=== PAUSE TestSuites/Exhaustive/rbd#02
=== CONT  TestSuites/Exhaustive/cephfs
=== CONT  TestSuites/Exhaustive/rbd
=== CONT  TestSuites/Exhaustive/rbd#02
=== RUN   TestSuites/Exhaustive/cephfs/Subscr
=== PAUSE TestSuites/Exhaustive/cephfs/Subscr
=== CONT  TestSuites/Exhaustive/cephfs/Subscr
=== RUN   TestSuites/Exhaustive/cephfs/Subscr/Deploy
=== CONT  TestSuites/Exhaustive/cephfs#02
2024-10-31T19:39:06.238+0200	INFO	subscr-cephfs	Deploying workload
=== RUN   TestSuites/Exhaustive/cephfs#02/Disapp
=== CONT  TestSuites/Exhaustive/cephfs#01
=== RUN   TestSuites/Exhaustive/cephfs#01/Appset
=== RUN   TestSuites/Exhaustive/rbd/Subscr
=== CONT  TestSuites/Exhaustive/rbd#01
=== PAUSE TestSuites/Exhaustive/rbd/Subscr
=== CONT  TestSuites/Exhaustive/rbd/Subscr
=== RUN   TestSuites/Exhaustive/rbd#02/Disapp
=== PAUSE TestSuites/Exhaustive/rbd#02/Disapp
=== CONT  TestSuites/Exhaustive/rbd#02/Disapp
=== PAUSE TestSuites/Exhaustive/cephfs#02/Disapp
=== CONT  TestSuites/Exhaustive/cephfs#02/Disapp
=== PAUSE TestSuites/Exhaustive/cephfs#01/Appset
=== NAME  TestSuites/Exhaustive/cephfs#02/Disapp
    exhaustive_suite_test.go:91: Workload cephfs not supported by deployer Disapp, skip test
=== CONT  TestSuites/Exhaustive/cephfs#01/Appset
=== RUN   TestSuites/Exhaustive/cephfs#01/Appset/Deploy
=== RUN   TestSuites/Exhaustive/rbd/Subscr/Deploy
2024-10-31T19:39:06.238+0200	INFO	appset-cephfs	Deploying workload
=== RUN   TestSuites/Exhaustive/rbd#02/Disapp/Deploy
2024-10-31T19:39:06.238+0200	INFO	subscr-rbd	Deploying workload
=== RUN   TestSuites/Exhaustive/rbd#01/Appset
=== PAUSE TestSuites/Exhaustive/rbd#01/Appset
=== CONT  TestSuites/Exhaustive/rbd#01/Appset
=== RUN   TestSuites/Exhaustive/rbd#01/Appset/Deploy
2024-10-31T19:39:06.239+0200	INFO	appset-rbd	Deploying workload
2024-10-31T19:39:06.239+0200	INFO	disapp-rbd	Deploying workload
=== RUN   TestSuites/Exhaustive/cephfs#01/Appset/Enable
2024-10-31T19:39:06.363+0200	INFO	appset-cephfs	Protecting workload
=== RUN   TestSuites/Exhaustive/rbd#01/Appset/Enable
2024-10-31T19:39:06.365+0200	INFO	appset-rbd	Protecting workload
2024-10-31T19:39:07.474+0200	INFO	disapp-rbd	Deployment is ready
2024-10-31T19:39:07.474+0200	INFO	disapp-rbd	Workload is ready
2024-10-31T19:39:07.474+0200	INFO	disapp-rbd	Workload deployed
=== RUN   TestSuites/Exhaustive/rbd#02/Disapp/Enable
2024-10-31T19:39:07.475+0200	INFO	disapp-rbd	Protecting workload
2024-10-31T19:39:07.489+0200	INFO	disapp-rbd	Creating drpc
2024-10-31T19:39:11.363+0200	INFO	subscr-cephfs	Subscription phase is Propagated
=== RUN   TestSuites/Exhaustive/cephfs/Subscr/Enable
2024-10-31T19:39:11.363+0200	INFO	subscr-cephfs	Protecting workload
2024-10-31T19:39:11.366+0200	INFO	subscr-cephfs	Workload running on dr2
2024-10-31T19:39:11.366+0200	INFO	subscr-cephfs	Annotating placement
2024-10-31T19:39:11.372+0200	INFO	subscr-cephfs	Creating drpc
2024-10-31T19:39:11.391+0200	INFO	subscr-rbd	Subscription phase is Propagated
=== RUN   TestSuites/Exhaustive/rbd/Subscr/Enable
2024-10-31T19:39:11.391+0200	INFO	subscr-rbd	Protecting workload
2024-10-31T19:39:11.467+0200	INFO	appset-rbd	Workload running on dr1
2024-10-31T19:39:11.467+0200	INFO	appset-rbd	Annotating placement
2024-10-31T19:39:11.467+0200	INFO	appset-cephfs	Workload running on dr2
2024-10-31T19:39:11.467+0200	INFO	appset-cephfs	Annotating placement
2024-10-31T19:39:11.467+0200	INFO	subscr-rbd	Workload running on dr1
2024-10-31T19:39:11.467+0200	INFO	subscr-rbd	Annotating placement
2024-10-31T19:39:11.485+0200	INFO	appset-cephfs	Creating drpc
2024-10-31T19:39:11.571+0200	INFO	appset-rbd	Creating drpc
2024-10-31T19:39:11.767+0200	INFO	subscr-rbd	Creating drpc
2024-10-31T19:40:37.560+0200	INFO	disapp-rbd	drpc is ready
=== RUN   TestSuites/Exhaustive/rbd#02/Disapp/Failover
2024-10-31T19:40:37.560+0200	INFO	disapp-rbd	Failing over workload
2024-10-31T19:40:37.560+0200	INFO	disapp-rbd	Failing over workload
2024-10-31T19:40:37.569+0200	INFO	disapp-rbd	drpc is ready
2024-10-31T19:40:37.573+0200	INFO	disapp-rbd	Updating drpc failover to dr2
2024-10-31T19:40:46.656+0200	INFO	appset-rbd	drpc is ready
=== RUN   TestSuites/Exhaustive/rbd#01/Appset/Failover
2024-10-31T19:40:46.656+0200	INFO	appset-rbd	Failing over workload
2024-10-31T19:40:46.659+0200	INFO	appset-rbd	drpc is ready
2024-10-31T19:40:46.665+0200	INFO	appset-rbd	Updating drpc failover to dr2
2024-10-31T19:40:46.880+0200	INFO	subscr-rbd	drpc is ready
=== RUN   TestSuites/Exhaustive/rbd/Subscr/Failover
2024-10-31T19:40:46.880+0200	INFO	subscr-rbd	Failing over workload
2024-10-31T19:40:46.882+0200	INFO	subscr-rbd	drpc is ready
2024-10-31T19:40:46.887+0200	INFO	subscr-rbd	Updating drpc failover to dr2
2024-10-31T19:41:07.604+0200	INFO	disapp-rbd	drpc progression is WaitOnUserToCleanUp
2024-10-31T19:41:07.604+0200	INFO	disapp-rbd	Cleaning up discovered apps from dr1
2024-10-31T19:41:11.604+0200	INFO	appset-cephfs	drpc is ready
=== RUN   TestSuites/Exhaustive/cephfs#01/Appset/Failover
2024-10-31T19:41:11.605+0200	INFO	appset-cephfs	Failing over workload
2024-10-31T19:41:11.607+0200	INFO	appset-cephfs	drpc is ready
2024-10-31T19:41:11.612+0200	INFO	appset-cephfs	Updating drpc failover to dr1
2024-10-31T19:41:16.699+0200	INFO	appset-rbd	drpc phase is FailedOver
2024-10-31T19:41:16.918+0200	INFO	subscr-rbd	drpc phase is FailedOver
2024-10-31T19:41:41.514+0200	INFO	subscr-cephfs	drpc is ready
=== RUN   TestSuites/Exhaustive/cephfs/Subscr/Failover
2024-10-31T19:41:41.514+0200	INFO	subscr-cephfs	Failing over workload
2024-10-31T19:41:41.516+0200	INFO	subscr-cephfs	drpc is ready
2024-10-31T19:41:41.521+0200	INFO	subscr-cephfs	Updating drpc failover to dr1
2024-10-31T19:42:11.551+0200	INFO	subscr-cephfs	drpc phase is FailedOver
2024-10-31T19:42:11.667+0200	INFO	appset-cephfs	drpc phase is FailedOver
2024-10-31T19:43:37.220+0200	INFO	disapp-rbd	drpc progression is Completed
2024-10-31T19:43:42.035+0200	INFO	subscr-rbd	drpc is ready
=== RUN   TestSuites/Exhaustive/rbd/Subscr/Relocate
2024-10-31T19:43:42.035+0200	INFO	subscr-rbd	Relocating workload
2024-10-31T19:43:42.040+0200	INFO	subscr-rbd	drpc is ready
2024-10-31T19:43:42.049+0200	INFO	subscr-rbd	Updating drpc relocate to dr1
2024-10-31T19:44:07.247+0200	INFO	disapp-rbd	drpc is ready
2024-10-31T19:44:07.258+0200	INFO	disapp-rbd	Deployment is ready
2024-10-31T19:44:07.258+0200	INFO	disapp-rbd	Workload is ready
=== RUN   TestSuites/Exhaustive/rbd#02/Disapp/Relocate
2024-10-31T19:44:07.258+0200	INFO	disapp-rbd	Relocating workload
2024-10-31T19:44:07.258+0200	INFO	disapp-rbd	Relocating workload
2024-10-31T19:44:07.268+0200	INFO	disapp-rbd	drpc is ready
2024-10-31T19:44:07.363+0200	INFO	disapp-rbd	Updating drpc relocate to dr1
2024-10-31T19:44:41.667+0200	INFO	subscr-cephfs	drpc is ready
=== RUN   TestSuites/Exhaustive/cephfs/Subscr/Relocate
2024-10-31T19:44:41.667+0200	INFO	subscr-cephfs	Relocating workload
2024-10-31T19:44:41.673+0200	INFO	subscr-cephfs	drpc is ready
2024-10-31T19:44:41.679+0200	INFO	subscr-cephfs	Updating drpc relocate to dr2
2024-10-31T19:44:46.858+0200	INFO	appset-rbd	drpc is ready
=== RUN   TestSuites/Exhaustive/rbd#01/Appset/Relocate
2024-10-31T19:44:46.858+0200	INFO	appset-rbd	Relocating workload
2024-10-31T19:44:46.860+0200	INFO	appset-rbd	drpc is ready
2024-10-31T19:44:46.864+0200	INFO	appset-rbd	Updating drpc relocate to dr1
2024-10-31T19:45:07.417+0200	INFO	disapp-rbd	drpc progression is WaitOnUserToCleanUp
2024-10-31T19:45:07.417+0200	INFO	disapp-rbd	Cleaning up discovered apps from dr2
2024-10-31T19:45:42.153+0200	INFO	subscr-rbd	drpc phase is Relocated
2024-10-31T19:46:12.177+0200	INFO	subscr-rbd	drpc is ready
=== RUN   TestSuites/Exhaustive/rbd/Subscr/Disable
2024-10-31T19:46:12.177+0200	INFO	subscr-rbd	Unprotecting workload
2024-10-31T19:46:12.177+0200	INFO	subscr-rbd	Deleting drpc
2024-10-31T19:46:37.198+0200	INFO	disapp-rbd	drpc progression is Completed
2024-10-31T19:46:37.201+0200	INFO	disapp-rbd	drpc is ready
2024-10-31T19:46:37.210+0200	INFO	disapp-rbd	Deployment is ready
2024-10-31T19:46:37.210+0200	INFO	disapp-rbd	Workload is ready
=== RUN   TestSuites/Exhaustive/rbd#02/Disapp/Disable
2024-10-31T19:46:37.210+0200	INFO	disapp-rbd	Unprotecting workload
2024-10-31T19:46:37.210+0200	INFO	disapp-rbd	Deleting drpc
2024-10-31T19:46:41.777+0200	INFO	subscr-cephfs	drpc phase is Relocated
2024-10-31T19:46:41.868+0200	INFO	appset-cephfs	drpc is ready
=== RUN   TestSuites/Exhaustive/cephfs#01/Appset/Relocate
2024-10-31T19:46:41.868+0200	INFO	appset-cephfs	Relocating workload
2024-10-31T19:46:41.870+0200	INFO	appset-cephfs	drpc is ready
2024-10-31T19:46:41.874+0200	INFO	appset-cephfs	Updating drpc relocate to dr2
2024-10-31T19:46:42.234+0200	INFO	subscr-rbd	drpc is deleted
=== RUN   TestSuites/Exhaustive/rbd/Subscr/Undeploy
2024-10-31T19:46:42.234+0200	INFO	subscr-rbd	Undeploying workload
2024-10-31T19:46:42.312+0200	INFO	subscr-rbd	Waiting until namespace subscr-rbd is deleted
2024-10-31T19:46:48.348+0200	INFO	subscr-rbd	Namespace subscr-rbd deleted
2024-10-31T19:47:07.247+0200	INFO	disapp-rbd	drpc is deleted
=== RUN   TestSuites/Exhaustive/rbd#02/Disapp/Undeploy
2024-10-31T19:47:07.257+0200	INFO	disapp-rbd	Undeploying workload
2024-10-31T19:47:07.260+0200	INFO	disapp-rbd	Deleting discovered apps on dr1
2024-10-31T19:47:09.146+0200	INFO	disapp-rbd	Deletting discovered apps on dr2
2024-10-31T19:47:09.968+0200	INFO	disapp-rbd	Deleting namespace disapp-rbd on dr1
2024-10-31T19:47:09.972+0200	INFO	disapp-rbd	Waiting until namespace disapp-rbd is deleted
2024-10-31T19:47:11.801+0200	INFO	subscr-cephfs	drpc is ready
=== RUN   TestSuites/Exhaustive/cephfs/Subscr/Disable
2024-10-31T19:47:11.801+0200	INFO	subscr-cephfs	Unprotecting workload
2024-10-31T19:47:11.801+0200	INFO	subscr-cephfs	Deleting drpc
2024-10-31T19:47:15.991+0200	INFO	disapp-rbd	Namespace disapp-rbd deleted
2024-10-31T19:47:15.991+0200	INFO	disapp-rbd	Deleting namespace disapp-rbd on dr2
2024-10-31T19:47:16.004+0200	INFO	disapp-rbd	Waiting until namespace disapp-rbd is deleted
2024-10-31T19:47:22.022+0200	INFO	disapp-rbd	Namespace disapp-rbd deleted
2024-10-31T19:47:22.022+0200	INFO	disapp-rbd	Workload undeployed
2024-10-31T19:47:41.835+0200	INFO	subscr-cephfs	drpc is deleted
=== RUN   TestSuites/Exhaustive/cephfs/Subscr/Undeploy
2024-10-31T19:47:41.835+0200	INFO	subscr-cephfs	Undeploying workload
2024-10-31T19:47:41.854+0200	INFO	subscr-cephfs	Waiting until namespace subscr-cephfs is deleted
2024-10-31T19:47:47.874+0200	INFO	subscr-cephfs	Namespace subscr-cephfs deleted
2024-10-31T19:50:12.020+0200	INFO	appset-cephfs	drpc phase is Relocated
2024-10-31T19:50:12.083+0200	INFO	appset-rbd	drpc phase is Relocated
2024-10-31T19:50:42.045+0200	INFO	appset-cephfs	drpc is ready
=== RUN   TestSuites/Exhaustive/cephfs#01/Appset/Disable
2024-10-31T19:50:42.045+0200	INFO	appset-cephfs	Unprotecting workload
2024-10-31T19:50:42.045+0200	INFO	appset-cephfs	Deleting drpc
2024-10-31T19:50:47.109+0200	INFO	appset-rbd	drpc is ready
=== RUN   TestSuites/Exhaustive/rbd#01/Appset/Disable
2024-10-31T19:50:47.110+0200	INFO	appset-rbd	Unprotecting workload
2024-10-31T19:50:47.110+0200	INFO	appset-rbd	Deleting drpc
2024-10-31T19:51:12.078+0200	INFO	appset-cephfs	drpc is deleted
=== RUN   TestSuites/Exhaustive/cephfs#01/Appset/Undeploy
2024-10-31T19:51:12.078+0200	INFO	appset-cephfs	Undeploying workload
2024-10-31T19:51:12.136+0200	INFO	appset-rbd	drpc is deleted
=== RUN   TestSuites/Exhaustive/rbd#01/Appset/Undeploy
2024-10-31T19:51:12.136+0200	INFO	appset-rbd	Undeploying workload
2024-10-31T19:51:12.200+0200	INFO	Channel ramen-gitops is deleted
2024-10-31T19:51:12.209+0200	INFO	Waiting until namespace ramen-samples is deleted
2024-10-31T19:51:18.230+0200	INFO	Namespace ramen-samples deleted
--- PASS: TestSuites (0.06s)
    --- PASS: TestSuites/Validate (0.06s)
        --- PASS: TestSuites/Validate/CheckRamenHubOperatorStatus (0.02s)
        --- PASS: TestSuites/Validate/CheckRamenSpokeOperatorStatus (0.03s)
    --- PASS: TestSuites/Exhaustive (6.05s)
        --- PASS: TestSuites/Exhaustive/cephfs#02 (0.00s)
            --- SKIP: TestSuites/Exhaustive/cephfs#02/Disapp (0.00s)
        --- PASS: TestSuites/Exhaustive/rbd (0.00s)
            --- PASS: TestSuites/Exhaustive/rbd/Subscr (462.11s)
                --- PASS: TestSuites/Exhaustive/rbd/Subscr/Deploy (5.15s)
                --- PASS: TestSuites/Exhaustive/rbd/Subscr/Enable (95.49s)
                --- PASS: TestSuites/Exhaustive/rbd/Subscr/Failover (175.16s)
                --- PASS: TestSuites/Exhaustive/rbd/Subscr/Relocate (150.14s)
                --- PASS: TestSuites/Exhaustive/rbd/Subscr/Disable (30.06s)
                --- PASS: TestSuites/Exhaustive/rbd/Subscr/Undeploy (6.11s)
        --- PASS: TestSuites/Exhaustive/rbd#02 (0.00s)
            --- PASS: TestSuites/Exhaustive/rbd#02/Disapp (495.78s)
                --- PASS: TestSuites/Exhaustive/rbd#02/Disapp/Deploy (1.24s)
                --- PASS: TestSuites/Exhaustive/rbd#02/Disapp/Enable (90.08s)
                --- PASS: TestSuites/Exhaustive/rbd#02/Disapp/Failover (209.70s)
                --- PASS: TestSuites/Exhaustive/rbd#02/Disapp/Relocate (149.95s)
                --- PASS: TestSuites/Exhaustive/rbd#02/Disapp/Disable (30.05s)
                --- PASS: TestSuites/Exhaustive/rbd#02/Disapp/Undeploy (14.76s)
        --- PASS: TestSuites/Exhaustive/cephfs (0.00s)
            --- PASS: TestSuites/Exhaustive/cephfs/Subscr (521.64s)
                --- PASS: TestSuites/Exhaustive/cephfs/Subscr/Deploy (5.12s)
                --- PASS: TestSuites/Exhaustive/cephfs/Subscr/Enable (150.15s)
                --- PASS: TestSuites/Exhaustive/cephfs/Subscr/Failover (180.15s)
                --- PASS: TestSuites/Exhaustive/cephfs/Subscr/Relocate (150.13s)
                --- PASS: TestSuites/Exhaustive/cephfs/Subscr/Disable (30.03s)
                --- PASS: TestSuites/Exhaustive/cephfs/Subscr/Undeploy (6.04s)
        --- PASS: TestSuites/Exhaustive/cephfs#01 (0.00s)
            --- PASS: TestSuites/Exhaustive/cephfs#01/Appset (725.88s)
                --- PASS: TestSuites/Exhaustive/cephfs#01/Appset/Deploy (0.12s)
                --- PASS: TestSuites/Exhaustive/cephfs#01/Appset/Enable (125.24s)
                --- PASS: TestSuites/Exhaustive/cephfs#01/Appset/Failover (330.26s)
                --- PASS: TestSuites/Exhaustive/cephfs#01/Appset/Relocate (240.19s)
                --- PASS: TestSuites/Exhaustive/cephfs#01/Appset/Disable (30.03s)
                --- PASS: TestSuites/Exhaustive/cephfs#01/Appset/Undeploy (0.02s)
        --- PASS: TestSuites/Exhaustive/rbd#01 (0.00s)
            --- PASS: TestSuites/Exhaustive/rbd#01/Appset (725.97s)
                --- PASS: TestSuites/Exhaustive/rbd#01/Appset/Deploy (0.13s)
                --- PASS: TestSuites/Exhaustive/rbd#01/Appset/Enable (100.29s)
                --- PASS: TestSuites/Exhaustive/rbd#01/Appset/Failover (240.20s)
                --- PASS: TestSuites/Exhaustive/rbd#01/Appset/Relocate (360.27s)
                --- PASS: TestSuites/Exhaustive/rbd#01/Appset/Disable (25.03s)
                --- PASS: TestSuites/Exhaustive/rbd#01/Appset/Undeploy (0.06s)
PASS
ok  	github.com/ramendr/ramen/e2e	733.185s

@nirs nirs force-pushed the e2e-log-format branch 2 times, most recently from 3da821e to f26a2e4 Compare October 31, 2024 18:26
@nirs nirs marked this pull request as ready for review October 31, 2024 18:55
This is the recommended way based on logr docs, probably to make it
easier to use, since you don't need to check if the logger is nil, and
zero value of a logger just discards data. This is also the way logr is
used in ramen, so there is no reason to use it differently in the e2e
code.

Part-of: RamenDR#1597
Signed-off-by: Nir Soffer <[email protected]>
This info is usually not helpful and harmful by taking spaces needed for
important info in the logs. When logging error we have file:lineno info
in the traceback.

Example log with this change:

    === RUN   TestSuites/Exhaustive/Deploy-cephfs#01/Appset/Enable
    2024-10-30T16:46:14.331+0200	INFO	enter EnableProtection appset-deploy-rbd-busybox
    2024-10-30T16:46:14.331+0200	INFO	enter EnableProtection appset-deploy-cephfs-busybox
    2024-10-30T16:46:16.995+0200	INFO	deployment busybox is ready
    2024-10-30T16:46:16.995+0200	INFO	workload Deploy-rbd is ready
    2024-10-30T16:46:16.995+0200	INFO	disapp-deploy-rbd-busybox is deployed

Part-of: RamenDR#1597
Signed-off-by: Nir Soffer <[email protected]>
We used to log everything using the global logger. This makes the log
messy and hard to follow, since we run 5 dr flows concurrently. This
will be worse as we add new workloads (e.g. flattened pvcs, cloned pvcs,
volsync with block pvc).

We use now per-test logger created using the name of the workload (e.g.
disapp-deploy-rbd-busybox). Every log message from test flow start with
this name. The rest of the log does not specify resources names since we
use the same name for all resources (drpc, placement, subscription,
etc).

Clean up log messages, replacing noisy text with simple description of
the event.

More work is needed, we still log too much uninteresting details, and do
no not log what we wait for, but this is already much easier to follow.

Example log with this change:

    === RUN   TestSuites/Exhaustive/Deploy-rbd/Subscr/Enable
    2024-10-31T00:37:41.913+0200	INFO	subscr-deploy-rbd-busybox	Protecting workload
    2024-10-31T00:37:41.913+0200	INFO	subscr-deploy-cephfs-busybox	Protecting workload
    2024-10-31T00:37:41.915+0200	INFO	appset-deploy-rbd-busybox	Workload running on dr2
    2024-10-31T00:37:41.915+0200	INFO	appset-deploy-rbd-busybox	Annotating placement
    2024-10-31T00:37:41.917+0200	INFO	subscr-deploy-rbd-busybox	Workload running on dr2
    2024-10-31T00:37:41.917+0200	INFO	subscr-deploy-rbd-busybox	Annotating placement
    2024-10-31T00:37:41.918+0200	INFO	subscr-deploy-cephfs-busybox	Workload running on dr1
    2024-10-31T00:37:41.918+0200	INFO	subscr-deploy-cephfs-busybox	Annotating placement
    2024-10-31T00:37:41.926+0200	INFO	appset-deploy-rbd-busybox	Creating drpc
    2024-10-31T00:37:41.930+0200	INFO	subscr-deploy-rbd-busybox	Creating drpc
    2024-10-31T00:37:41.932+0200	INFO	subscr-deploy-cephfs-busybox	Creating drpc
    2024-10-31T00:38:52.038+0200	INFO	appset-deploy-cephfs-busybox	drpc is ready

Part-of: RamenDR#1597
Signed-off-by: Nir Soffer <[email protected]>
Adding the same text to all workload is not helpful. Shorter names
are important to make it easy to scan the logs.

Currently with test everything with deployment using busybox image. When
we will add new workload we can consider changing the names, but we need
just one word to make the workload unique.

I want to add vm based tests later, but these will run with a special
environment, so they can use different test suite.

Example logs with this change:

    2024-10-31T19:39:11.391+0200	INFO	subscr-rbd	Protecting workload
    2024-10-31T19:39:11.467+0200	INFO	appset-rbd	Workload running on dr1
    2024-10-31T19:39:11.467+0200	INFO	appset-rbd	Annotating placement
    2024-10-31T19:39:11.467+0200	INFO	appset-cephfs	Workload running on dr2
    2024-10-31T19:39:11.467+0200	INFO	appset-cephfs	Annotating placement
    2024-10-31T19:39:11.467+0200	INFO	subscr-rbd	Workload running on dr1
    2024-10-31T19:39:11.467+0200	INFO	subscr-rbd	Annotating placement
    2024-10-31T19:39:11.485+0200	INFO	appset-cephfs	Creating drpc
    2024-10-31T19:39:11.571+0200	INFO	appset-rbd	Creating drpc
    2024-10-31T19:39:11.767+0200	INFO	subscr-rbd	Creating drpc
    2024-10-31T19:40:37.560+0200	INFO	disapp-rbd	drpc is ready

Fixes: RamenDR#1597
Signed-off-by: Nir Soffer <[email protected]>
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 follow workload events
2 participants