Merge pull request #197 from Kuadrant/gh-117

Update logging

README.md

@@ -103,6 +103,52 @@ make manifests
 
 More information can be found via the [Kubebuilder Documentation](https://book.kubebuilder.io/introduction.html)
 
+## Logging
+Logs are following the general guidelines: 
+- `logger.Info()` describe a high-level state of the resource such as creation, deletion and which reconciliation path was taken.  
+- `logger.Error()` describe only those errors that are not returned in the result of the reconciliation. If error is occurred there should be only one error message. 
+- `logger.V(1).Info()` debug level logs to give information about every change or event caused by the resource as well as every update of the resource.
+
+The `--zap-devel` argument will enable debug level logs for the output. Otherwise, all `V()` logs are ignored.
+
+### Common metadata 
+Not exhaustive list of metadata for DNSRecord controller:
+- `level` - logging level. Values are: `info`,`debug` or `error`
+- `ts` - timestamp
+- `logger` - logger name
+- `msg`
+- `controller` and `controllerKind` - controller name, and it's kind respectively to output the log
+- `DNSRecord` - name and namespace of the DNS Record CR that is being reconciled
+- `reconcileID`
+- `ownerID` - ID the of owner of the DNS Record 
+- `txtPrefix`/`txtSuffix` - prefix and suffix of the TXT record in provider. 
+- `zoneEndpoints` - endpoints that exist in the provider
+- `specEdnoinds` - endpoints defined in the spec
+- `statusEndpoints` - endpoints that were processed previously
+
+> Note that not all the metadata values are present at each of the logs statements. 
+
+### Examples
+To query logs locally you can use `jq`. For example:
+Retrieve logs by 
+```shell
+kubectl get deployments -l app.kubernetes.io/part-of=dns-operator -A
+
+NAMESPACE             NAME                              READY 
+dns-operator-system   dns-operator-controller-manager   1/1   
+```
+And query them. For example:
+```shell
+kubectl logs -l control-plane=dns-operator-controller-manager -n dns-operator-system --tail -1 | sed '/^{/!d' | jq 'select(.controller=="dnsrecord" and .level=="info")'
+```
+or 
+```shell
+kubectl logs -l control-plane=dns-operator-controller-manager -n dns-operator-system --tail -1 | sed '/^{/!d' | jq 'select(.controller=="dnsrecord" and .DNSRecord.name=="test" and .reconcileID=="2be16b6d-b90f-430e-9996-8b5ec4855d53")' | jq '.level, .msg, .zoneEndpoints, .specEndpoints, .statusEndpoints '
+
+```
+You could use selector in the `jq` with `and`/`not`/`or` to restrict.
+
+
 ## License
 
 Copyright 2024.

internal/controller/dnsrecord_controller.go

@@ -79,7 +79,7 @@ func (r *DNSRecordReconciler) Reconcile(ctx context.Context, req ctrl.Request) (
 	logger := log.FromContext(ctx).WithName("dnsrecord_controller")
 	ctx = log.IntoContext(ctx, logger)
 
-	logger.V(1).Info("Reconciling DNSRecord")
+	logger.Info("Reconciling DNSRecord")
 
 	reconcileStart = metav1.Now()
 
@@ -126,6 +126,7 @@ func (r *DNSRecordReconciler) Reconcile(ctx context.Context, req ctrl.Request) (
 	ctx = log.IntoContext(ctx, logger)
 
 	if dnsRecord.DeletionTimestamp != nil && !dnsRecord.DeletionTimestamp.IsZero() {
+		logger.Info("Deleting DNSRecord")
 		if err = r.ReconcileHealthChecks(ctx, dnsRecord, managedZone); client.IgnoreNotFound(err) != nil {
 			return ctrl.Result{}, err
 		}
@@ -141,7 +142,7 @@ func (r *DNSRecordReconciler) Reconcile(ctx context.Context, req ctrl.Request) (
 			return ctrl.Result{RequeueAfter: randomizedValidationRequeue}, nil
 		}
 
-		logger.Info("Removing Finalizer", "name", DNSRecordFinalizer)
+		logger.Info("Removing Finalizer", "finalizer_name", DNSRecordFinalizer)
 		controllerutil.RemoveFinalizer(dnsRecord, DNSRecordFinalizer)
 		if err = r.Update(ctx, dnsRecord); client.IgnoreNotFound(err) != nil {
 			if apierrors.IsConflict(err) {
@@ -154,7 +155,7 @@ func (r *DNSRecordReconciler) Reconcile(ctx context.Context, req ctrl.Request) (
 
 	if !controllerutil.ContainsFinalizer(dnsRecord, DNSRecordFinalizer) {
 		dnsRecord.Status.QueuedFor = metav1.NewTime(reconcileStart.Add(randomizedValidationRequeue))
-		logger.Info("Adding Finalizer", "name", DNSRecordFinalizer)
+		logger.Info("Adding Finalizer", "finalizer_name", DNSRecordFinalizer)
 		controllerutil.AddFinalizer(dnsRecord, DNSRecordFinalizer)
 		err = r.Update(ctx, dnsRecord)
 		if err != nil {
@@ -164,6 +165,7 @@ func (r *DNSRecordReconciler) Reconcile(ctx context.Context, req ctrl.Request) (
 	}
 
 	if !common.Owns(managedZone, dnsRecord) {
+		logger.V(1).Info("Record is not owned by ManagedZone", "ManagedZoneName", managedZone.Name)
 		err = common.EnsureOwnerRef(managedZone, dnsRecord, true)
 		if err != nil {
 			return ctrl.Result{}, err
@@ -207,6 +209,7 @@ func (r *DNSRecordReconciler) updateStatus(ctx context.Context, previous, curren
 
 	// failure
 	if specErr != nil {
+		logger.Error(specErr, "Error reconciling DNS Record")
 		var updateError error
 		if !equality.Semantic.DeepEqual(previous.Status, current.Status) {
 			if updateError = r.Status().Update(ctx, current); updateError != nil && apierrors.IsConflict(updateError) {
@@ -255,14 +258,15 @@ func (r *DNSRecordReconciler) updateStatus(ctx context.Context, previous, curren
 
 	// update the record after setting the status
 	if !equality.Semantic.DeepEqual(previous.Status, current.Status) {
+		logger.V(1).Info("Updating status of DNSRecord")
 		if updateError := r.Status().Update(ctx, current); updateError != nil {
 			if apierrors.IsConflict(updateError) {
 				return ctrl.Result{Requeue: true}, nil
 			}
 			return ctrl.Result{}, updateError
 		}
 	}
-
+	logger.V(1).Info(fmt.Sprintf("Requeue in %s", requeueTime.String()))
 	return ctrl.Result{RequeueAfter: requeueTime}, nil
 }
 
@@ -333,7 +337,7 @@ func (r *DNSRecordReconciler) publishRecord(ctx context.Context, dnsRecord *v1al
 	}
 
 	if prematurely, _ := recordReceivedPrematurely(dnsRecord); prematurely {
-		logger.V(1).Info("Skipping managed zone to which the DNS dnsRecord is already published and is still valid", "managedZone", managedZone.Name)
+		logger.V(1).Info("Skipping DNSRecord - is still valid", "managedZone", managedZone.Name)
 		return false, nil
 	}
 

internal/controller/dnsrecord_controller_test.go

@@ -301,6 +301,7 @@ var _ = Describe("DNSRecordReconciler", func() {
 			g.Expect(err).To(MatchError(ContainSubstring("not found")))
 		}, 5*time.Second, time.Second, ctx).Should(Succeed())
 	})
+
 	It("should have ready condition with status true", func() {
 		Expect(k8sClient.Create(ctx, dnsRecord)).To(Succeed())
 		Eventually(func(g Gomega) {