From 17cff40d967ac61d3c3fd62dbc2915720c24cd80 Mon Sep 17 00:00:00 2001 From: Maskym Vavilov Date: Wed, 24 Jul 2024 14:36:13 +0100 Subject: [PATCH] Update logging Signed-off-by: Maskym Vavilov --- README.md | 46 +++++++++++++++++++ internal/controller/dnsrecord_controller.go | 14 ++++-- .../controller/dnsrecord_controller_test.go | 1 + 3 files changed, 56 insertions(+), 5 deletions(-) diff --git a/README.md b/README.md index 3765c471..545e589d 100644 --- a/README.md +++ b/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. diff --git a/internal/controller/dnsrecord_controller.go b/internal/controller/dnsrecord_controller.go index 15317e86..67be985f 100644 --- a/internal/controller/dnsrecord_controller.go +++ b/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,6 +258,7 @@ 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 @@ -262,7 +266,7 @@ func (r *DNSRecordReconciler) updateStatus(ctx context.Context, previous, curren 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 } diff --git a/internal/controller/dnsrecord_controller_test.go b/internal/controller/dnsrecord_controller_test.go index 2e0e2623..88c54a62 100644 --- a/internal/controller/dnsrecord_controller_test.go +++ b/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) {