2110554 – [DR] Ramen operator logs time is not in human-readable format

Bug 2110554 - [DR] Ramen operator logs time is not in human-readable format

Summary: [DR] Ramen operator logs time is not in human-readable format

Keywords:
Status:	CLOSED CURRENTRELEASE
Alias:	None
Product:	Red Hat OpenShift Data Foundation
Classification:	Red Hat Storage
Component:	odf-dr
Sub Component:
Version:	4.11
Hardware:	Unspecified
OS:	Unspecified
Priority:	unspecified
Severity:	unspecified
Target Milestone:	---
Target Release:	ODF 4.12.0
Assignee:	Shyamsundar
QA Contact:	kmanohar
Docs Contact:
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+	depends on / blocked

Reported:	2022-07-25 15:37 UTC by Pratik Surve
Modified:	2023-08-09 17:00 UTC (History)
CC List:	3 users (show)
Fixed In Version:
Doc Type:	No Doc Update
Doc Text:
Clone Of:
Environment:
Last Closed:	2023-02-08 14:06:28 UTC
Embargoed:

Attachments	(Terms of Use)

Links
System	ID	Private	Priority	Status	Summary	Last Updated
Github	RamenDR ramen pull 499	0	None	Merged	Use ISO 8601 timestamp format in logs	2022-09-26 22:17:41 UTC

Description Pratik Surve 2022-07-25 15:37:20 UTC

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

Comment 2 Shyamsundar 2022-07-25 15:41:27 UTC

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.

Comment 5 Mudit Agarwal 2022-08-03 08:17:17 UTC

Moving this to 4.12 after an offline discussion with Karthick, this is a cosmetic fix and can wait till next release.

Comment 9 kmanohar 2022-11-30 10:33:10 UTC

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"}

Note You need to log in before you can comment on or make changes to this bug.