Bug 2110554
| Summary: | [DR] Ramen operator logs time is not in human-readable format | ||
|---|---|---|---|
| Product: | [Red Hat Storage] Red Hat OpenShift Data Foundation | Reporter: | Pratik Surve <prsurve> |
| Component: | odf-dr | Assignee: | Shyamsundar <srangana> |
| odf-dr sub component: | ramen | QA Contact: | kmanohar |
| Status: | CLOSED CURRENTRELEASE | Docs Contact: | |
| Severity: | unspecified | ||
| Priority: | unspecified | CC: | muagarwa, ocs-bugs, odf-bz-bot |
| Version: | 4.11 | ||
| Target Milestone: | --- | ||
| Target Release: | ODF 4.12.0 | ||
| Hardware: | Unspecified | ||
| OS: | Unspecified | ||
| Whiteboard: | |||
| Fixed In Version: | Doc Type: | No Doc Update | |
| Doc Text: | Story Points: | --- | |
| Clone Of: | Environment: | ||
| Last Closed: | 2023-02-08 14:06:28 UTC | Type: | Bug |
| Regression: | --- | Mount Type: | --- |
| Documentation: | --- | CRM: | |
| Verified Versions: | Category: | --- | |
| oVirt Team: | --- | RHEL 7.3 requirements from Atomic Host: | |
| Cloudforms Team: | --- | Target Upstream Version: | |
| Embargoed: | |||
This is currently cosmetic for the following reasons: - oc logs, if provided with the --timestamps option returns the required time format in human readable formats - must gather uses the --timestamps option, allowing user provided logs to be parsed easily The fix for this is already provided upstream: https://github.com/RamenDR/ramen/pull/499 @muagarwa or @kramdoss Propose we move this out of 4.11, but if deemed critical/must-fix we can backport the same to the downstream branch. Moving this to 4.12 after an offline discussion with Karthick, this is a cosmetic fix and can wait till next release. VERIFICATIONS COMMENTS :-
Problem:-
[DR] Ramen operator logs time is not in human-readable format
--Snippet from ramen hub operator
1.6587628601184e+09 INFO controllers.DRPlacementControl controllers/drplacementcontrol_controller.go:357 PlacementRule Status is: ({Decisions:[{ClusterName:vmware-dccp-one ClusterNamespace:vmware-dccp-one}]})
1.658762860118457e+09 INFO controllers.DRPlacementControl controllers/drplacementcontrol_controller.go:484 Starting to process placement
1.6587628601184642e+09 INFO controllers.DRPlacementControl controllers/drplacementcontrol.go:76 Process DRPC Placement {"DRAction": ""}
1.6587628601184764e+09 INFO controllers.DRPlacementControl controllers/drplacementcontrol.go:109 Running initial deployment
1.6587628601184833e+09 INFO controllers.DRPlacementControl controllers/drplacementcontrol.go:109 Using homeCluster vmware-dccp-one for initial deployment, uPlRule Decision [{ClusterName:vmware-dccp-one ClusterNamespace:vmware-dccp-one}]
1.6587628601184928e+09 INFO controllers.DRPlacementControl controllers/drplacementcontrol.go:217 isAlreadyDeployedAndProtected? - ["vmware-dccp-one"]
1.658762860118499e+09 INFO controllers.DRPlacementControl controllers/drplacementcontrol.go:141 Already deployed on homeCluster vmware-dccp-one. Last state: Deployed
Expected results - timestamp should be in human-readable format
________________________________________________________________________________________________
Verified on - 4.12.0-120
ACM Version - DOWNSTREAM-2022-11-17-03-53-08
Ramen hub operator logs
2022-11-30T05:28:44.309Z INFO controllers.drpolicy util/secrets_util.go:489 Add Secret {"name": "dr-policy-5m", "rid": "75ebb162-dc10-4b91-b3a0-dad405918953", "cluster": "kmanohar-clu1", "secret": "0eb4d5937ba374896ab0a0f1f8d824acedbecc4"}
2022-11-30T05:28:44.313Z INFO controllers.drpolicy util/secrets_util.go:489 Add Secret {"name": "dr-policy-5m", "rid": "75ebb162-dc10-4b91-b3a0-dad405918953", "cluster": "kmanohar-clu1", "secret": "b6a6f041c1181265bbc16e669ce8d5201dbd902"}
2022-11-30T05:28:44.324Z INFO controllers.drpolicy util/secrets_util.go:489 Add Secret {"name": "dr-policy-5m", "rid": "75ebb162-dc10-4b91-b3a0-dad405918953", "cluster": "kmanohar-clu2", "secret": "0eb4d5937ba374896ab0a0f1f8d824acedbecc4"}
2022-11-30T05:28:44.333Z INFO controllers.drpolicy util/secrets_util.go:489 Add Secret {"name": "dr-policy-5m", "rid": "75ebb162-dc10-4b91-b3a0-dad405918953", "cluster": "kmanohar-clu2", "secret": "b6a6f041c1181265bbc16e669ce8d5201dbd902"}
2022-11-30T05:28:44.340Z INFO controllers.drpolicy util/conditions.go:31 condition unchanged {"name": "dr-policy-5m", "rid": "75ebb162-dc10-4b91-b3a0-dad405918953", "type": "Validated", "status": "True", "reason": "Succeeded", "message": "drpolicy validated", "generation": 2}
2022-11-30T05:28:44.340Z INFO controllers.drpolicy controllers/drpolicy_controller.go:109 reconcile exit {"name": "dr-policy-5m", "rid": "75ebb162-dc10-4b91-b3a0-dad405918953"}
2022-11-30T05:28:50.413Z INFO controllers.drcluster volsync/deploy_volsync.go:77 VolSync ManagedClusterAddOn createOrUpdate Complete {"name": "kmanohar-clu1", "rid": "8cec1fc8-546e-4263-8d99-0cd0f79bdb51", "managedClusterName": "kmanohar-clu1", "op": "unchanged"}
2022-11-30T05:28:50.413Z INFO controllers.drcluster util/mw_util.go:383 ManifestWork exists. {"name": "kmanohar-clu1", "rid": "8cec1fc8-546e-4263-8d99-0cd0f79bdb51", "name": "ramen-dr-cluster", "namespace": "kmanohar-clu1"}
2022-11-30T05:28:50.880Z INFO controllers.drcluster controllers/drcluster_controller.go:290 Nothing to update {Phase:Available Conditions:[{Type:Fenced Status:False ObservedGeneration:1 LastTransitionTime:2022-11-29 16:18:09 +0000 UTC Reason:Clean Message:Cluster Clean} {Type:Clean Status:True ObservedGeneration:1 LastTransitionTime:2022-11-29 16:18:09 +0000 UTC Reason:Clean Message:Cluster Clean} {Type:Validated Status:True ObservedGeneration:1 LastTransitionTime:2022-11-29 16:18:10 +0000 UTC Reason:Succeeded Message:Validated the cluster}]} {"name": "kmanohar-clu1", "rid": "8cec1fc8-546e-4263-8d99-0cd0f79bdb51"}
2022-11-30T05:28:50.880Z INFO controllers.drcluster controllers/drcluster_controller.go:149 reconcile exit {"name": "kmanohar-clu1", "rid": "8cec1fc8-546e-4263-8d99-0cd0f79bdb51"}
2022-11-30T05:28:50.880Z INFO controllers.drcluster controllers/drcluster_controller.go:85 reconcile enter {"name": "kmanohar-clu2", "rid": "ddb0572a-0cb0-4994-9aef-85b36027d6e0"}
2022-11-30T05:28:50.889Z INFO controllers.drcluster controllers/drcluster_controller.go:117 create/update {"name": "kmanohar-clu2", "rid": "ddb0572a-0cb0-4994-9aef-85b36027d6e0"}
2022-11-30T05:28:50.890Z INFO controllers.drcluster volsync/deploy_volsync.go:45 Reconciling VolSync ManagedClusterAddOn {"name": "kmanohar-clu2", "rid": "ddb0572a-0cb0-4994-9aef-85b36027d6e0", "managedClusterName": "kmanohar-clu2"}
2022-11-30T05:28:50.896Z INFO controllers.drcluster volsync/deploy_volsync.go:77 VolSync ManagedClusterAddOn createOrUpdate Complete {"name": "kmanohar-clu2", "rid": "ddb0572a-0cb0-4994-9aef-85b36027d6e0", "managedClusterName": "kmanohar-clu2", "op": "unchanged"}
2022-11-30T05:28:50.896Z INFO controllers.drcluster util/mw_util.go:383 ManifestWork exists. {"name": "kmanohar-clu2", "rid": "ddb0572a-0cb0-4994-9aef-85b36027d6e0", "name": "ramen-dr-cluster", "namespace": "kmanohar-clu2"}
2022-11-30T05:28:51.286Z INFO controllers.drcluster controllers/drcluster_controller.go:290 Nothing to update {Phase:Available Conditions:[{Type:Fenced Status:False ObservedGeneration:1 LastTransitionTime:2022-11-29 16:18:10 +0000 UTC Reason:Clean Message:Cluster Clean} {Type:Clean Status:True ObservedGeneration:1 LastTransitionTime:2022-11-29 16:18:10 +0000 UTC Reason:Clean Message:Cluster Clean} {Type:Validated Status:True ObservedGeneration:1 LastTransitionTime:2022-11-29 16:18:10 +0000 UTC Reason:Succeeded Message:Validated the cluster}]} {"name": "kmanohar-clu2", "rid": "ddb0572a-0cb0-4994-9aef-85b36027d6e0"}
2022-11-30T05:28:51.286Z INFO controllers.drcluster controllers/drcluster_controller.go:149 reconcile exit {"name": "kmanohar-clu2", "rid": "ddb0572a-0cb0-4994-9aef-85b36027d6e0"}
|
Description of problem (please be detailed as possible and provide log snippets): [DR] Ramen operator logs time is not in human-readable format --Snippet from ramen hub operator 1.6587628601184e+09 INFO controllers.DRPlacementControl controllers/drplacementcontrol_controller.go:357 PlacementRule Status is: ({Decisions:[{ClusterName:vmware-dccp-one ClusterNamespace:vmware-dccp-one}]}) 1.658762860118457e+09 INFO controllers.DRPlacementControl controllers/drplacementcontrol_controller.go:484 Starting to process placement 1.6587628601184642e+09 INFO controllers.DRPlacementControl controllers/drplacementcontrol.go:76 Process DRPC Placement {"DRAction": ""} 1.6587628601184764e+09 INFO controllers.DRPlacementControl controllers/drplacementcontrol.go:109 Running initial deployment 1.6587628601184833e+09 INFO controllers.DRPlacementControl controllers/drplacementcontrol.go:109 Using homeCluster vmware-dccp-one for initial deployment, uPlRule Decision [{ClusterName:vmware-dccp-one ClusterNamespace:vmware-dccp-one}] 1.6587628601184928e+09 INFO controllers.DRPlacementControl controllers/drplacementcontrol.go:217 isAlreadyDeployedAndProtected? - ["vmware-dccp-one"] 1.658762860118499e+09 INFO controllers.DRPlacementControl controllers/drplacementcontrol.go:141 Already deployed on homeCluster vmware-dccp-one. Last state: Deployed 1.6587628601185048e+09 INFO controllers.DRPlacementControl controllers/drplacementcontrol.go:167 Ensure VolSync replication has been setup for cluster vmware-dccp-one 1.6587628601185105e+09 INFO controllers.DRPlacementControl controllers/drplacementcontrolvolsync.go:21 Checking if there are PVCs for VolSync replication... {"cluster": "vmware-dccp-one"} 1.6587628601185186e+09 INFO controllers.DRPlacementControl controllers/drplacementcontrol.go:167 No PVCs found that require VolSync replication 1.6587628601185603e+09 INFO controllers.DRPlacementControl controllers/drplacementcontrol_controller.go:484 Completed processing placement {"requeue": false} 1.658762860118568e+09 INFO controllers.DRPlacementControl controllers/drplacementcontrol_controller.go:373 Finished processing {"Requeue?": false} 1.6587628601185758e+09 INFO controllers.DRPlacementControl controllers/drplacementcontrol_controller.go:373 Done reconciling {"state": "Deployed"} 1.6587628601185858e+09 INFO controllers.DRPlacementControl controllers/drplacementcontrol_controller.go:373 Requeue time {"duration": "9m59.881414596s"} 1.658762860118596e+09 INFO controllers.DRPlacementControl controller/controller.go:114 Exiting reconcile loop {"DRPC": "busybox-workloads-2/busybox-drpc"} Version of all relevant components (if applicable): OCP version:- 4.11.0-0.nightly-2022-07-19-104004 ODF version:- 4.11.0-123 CEPH version:- ceph version 16.2.8-79.el8cp (b49680b5658a09188897100c9224ae968e0b6c5b) pacific (stable) ACM version:- 2.5.1 Does this issue impact your ability to continue to work with the product (please explain in detail what is the user impact)? Is there any workaround available to the best of your knowledge? Rate from 1 - 5 the complexity of the scenario you performed that caused this bug (1 - very simple, 5 - very complex)? 1 Can this issue reproducible? Can this issue reproduce from the UI? If this is a regression, please provide more details to justify this: Steps to Reproduce: 1. 2. 3. Actual results: 1.6587628601184e+09 INFO controllers.DRPlacementControl controllers/drplacementcontrol_controller.go:357 PlacementRule Status is: ({Decisions:[{ClusterName:vmware-dccp-one ClusterNamespace:vmware-dccp-one}]}) 1.658762860118457e+09 INFO controllers.DRPlacementControl controllers/drplacementcontrol_controller.go:484 Starting to process placement 1.6587628601184642e+09 INFO controllers.DRPlacementControl controllers/drplacementcontrol.go:76 Process DRPC Placement {"DRAction": ""} 1.6587628601184764e+09 INFO controllers.DRPlacementControl controllers/drplacementcontrol.go:109 Running initial deployment 1.6587628601184833e+09 INFO controllers.DRPlacementControl controllers/drplacementcontrol.go:109 Using homeCluster vmware-dccp-one for initial deployment, uPlRule Decision [{ClusterName:vmware-dccp-one ClusterNamespace:vmware-dccp-one}] 1.6587628601184928e+09 INFO controllers.DRPlacementControl controllers/drplacementcontrol.go:217 isAlreadyDeployedAndProtected? - ["vmware-dccp-one"] 1.658762860118499e+09 INFO controllers.DRPlacementControl controllers/drplacementcontrol.go:141 Already deployed on homeCluster vmware-dccp-one. Last state: Deployed 1.6587628601185048e+09 INFO controllers.DRPlacementControl controllers/drplacementcontrol.go:167 Ensure VolSync replication has been setup for cluster vmware-dccp-one 1.6587628601185105e+09 INFO controllers.DRPlacementControl controllers/drplacementcontrolvolsync.go:21 Checking if there are PVCs for VolSync replication... {"cluster": "vmware-dccp-one"} 1.6587628601185186e+09 INFO controllers.DRPlacementControl controllers/drplacementcontrol.go:167 No PVCs found that require VolSync replication 1.6587628601185603e+09 INFO controllers.DRPlacementControl controllers/drplacementcontrol_controller.go:484 Completed processing placement {"requeue": false} 1.658762860118568e+09 INFO controllers.DRPlacementControl controllers/drplacementcontrol_controller.go:373 Finished processing {"Requeue?": false} 1.6587628601185758e+09 INFO controllers.DRPlacementControl controllers/drplacementcontrol_controller.go:373 Done reconciling {"state": "Deployed"} 1.6587628601185858e+09 INFO controllers.DRPlacementControl controllers/drplacementcontrol_controller.go:373 Requeue time {"duration": "9m59.881414596s"} 1.658762860118596e+09 INFO controllers.DRPlacementControl controller/controller.go:114 Exiting reconcile loop {"DRPC": "busybox-workloads-2/busybox-drpc"} Expected results: Additional info: We see issue in both operator ramen-hub and ramen-dr operator