From e7c3af65858cdf2eb4f9e377df460efb6d886500 Mon Sep 17 00:00:00 2001 From: Matt Knop Date: Mon, 9 Oct 2023 14:30:39 -0600 Subject: [PATCH] tracing reconciliation log output with an rid (#190) * adding rid to trace logging by reconciliation * removing unused line * adding rid for namespacereservation controller * Adding rid to ctx * updated changes with context * adjustments to logging through context --- .../clowdenvironment_controller.go | 14 ++++-- controllers/cloud.redhat.com/helpers/types.go | 2 + .../namespacepool_controller.go | 20 ++++---- .../namespacereservation_controller.go | 46 ++++++++++--------- 4 files changed, 48 insertions(+), 34 deletions(-) diff --git a/controllers/cloud.redhat.com/clowdenvironment_controller.go b/controllers/cloud.redhat.com/clowdenvironment_controller.go index f89513c9..24ff77ed 100644 --- a/controllers/cloud.redhat.com/clowdenvironment_controller.go +++ b/controllers/cloud.redhat.com/clowdenvironment_controller.go @@ -23,6 +23,7 @@ import ( clowder "github.com/RedHatInsights/clowder/apis/cloud.redhat.com/v1alpha1" "github.com/RedHatInsights/ephemeral-namespace-operator/controllers/cloud.redhat.com/helpers" + "github.com/RedHatInsights/rhc-osdk-utils/utils" "github.com/go-logr/logr" "github.com/prometheus/client_golang/prometheus" "k8s.io/apimachinery/pkg/runtime" @@ -44,9 +45,12 @@ type ClowdenvironmentReconciler struct { //+kubebuilder:rbac:groups=cloud.redhat.com,resources=clowdenvironments/status,verbs=get func (r *ClowdenvironmentReconciler) Reconcile(ctx context.Context, req ctrl.Request) (ctrl.Result, error) { + log := r.log.WithValues("rid", utils.RandString(5)) + ctx = context.WithValue(ctx, helpers.ErrType("log"), &log) + env := clowder.ClowdEnvironment{} if err := r.client.Get(ctx, req.NamespacedName, &env); err != nil { - r.log.Error(err, "Error retrieving clowdenv", "env-name", env.Name) + log.Error(err, "Error retrieving clowdenv", "env-name", env.Name) return ctrl.Result{}, err } @@ -54,14 +58,14 @@ func (r *ClowdenvironmentReconciler) Reconcile(ctx context.Context, req ctrl.Req return ctrl.Result{Requeue: true}, err } - r.log.Info( + log.Info( "Reconciling clowdenv", "env-name", env.Name, "deployments", fmt.Sprintf("%d / %d", env.Status.Deployments.ReadyDeployments, env.Status.Deployments.ManagedDeployments), ) namespaceName := env.Spec.TargetNamespace - r.log.Info("clowdenvironment ready", "namespace", namespaceName) + log.Info("clowdenvironment ready", "namespace", namespaceName) if err := helpers.CreateFrontendEnv(ctx, r.client, namespaceName, env); err != nil { r.log.Error(err, "error encountered with frontend environment", "namespace", namespaceName) @@ -70,7 +74,7 @@ func (r *ClowdenvironmentReconciler) Reconcile(ctx context.Context, req ctrl.Req } } - r.log.Info("namespace ready", "namespace", namespaceName) + log.Info("namespace ready", "namespace", namespaceName) if err := helpers.UpdateAnnotations(ctx, r.client, namespaceName, helpers.AnnotationEnvReady.ToMap()); err != nil { return ctrl.Result{Requeue: true}, fmt.Errorf("error setting annotations: %w", err) } @@ -94,7 +98,7 @@ func (r *ClowdenvironmentReconciler) Reconcile(ctx context.Context, req ctrl.Req namespace, err = helpers.GetNamespace(ctx, r.client, namespaceName) if err != nil { - r.log.Error(err, "could not retrieve newly created namespace", "namespace", namespaceName) + log.Error(err, "could not retrieve newly created namespace", "namespace", namespaceName) } if err := r.client.Update(ctx, &namespace); err != nil { diff --git a/controllers/cloud.redhat.com/helpers/types.go b/controllers/cloud.redhat.com/helpers/types.go index a34b9576..708a700e 100644 --- a/controllers/cloud.redhat.com/helpers/types.go +++ b/controllers/cloud.redhat.com/helpers/types.go @@ -41,3 +41,5 @@ var AnnotationReservedTrue = CustomAnnotation{Annotation: AnnotationReserved, Va var AnnotationReservedFalse = CustomAnnotation{Annotation: AnnotationReserved, Value: FalseValue} var LabelOperatorNamespaceTrue = CustomLabel{Label: LabelOperatorNS, Value: TrueValue} + +type ErrType string diff --git a/controllers/cloud.redhat.com/namespacepool_controller.go b/controllers/cloud.redhat.com/namespacepool_controller.go index fc244079..2f81b445 100644 --- a/controllers/cloud.redhat.com/namespacepool_controller.go +++ b/controllers/cloud.redhat.com/namespacepool_controller.go @@ -32,6 +32,7 @@ import ( crd "github.com/RedHatInsights/ephemeral-namespace-operator/apis/cloud.redhat.com/v1alpha1" "github.com/RedHatInsights/ephemeral-namespace-operator/controllers/cloud.redhat.com/helpers" + "github.com/RedHatInsights/rhc-osdk-utils/utils" ) // NamespacePoolReconciler reconciles a NamespacePool object @@ -46,21 +47,24 @@ type NamespacePoolReconciler struct { //+kubebuilder:rbac:groups=cloud.redhat.com,resources=namespacepools/finalizers,verbs=update func (r *NamespacePoolReconciler) Reconcile(ctx context.Context, req ctrl.Request) (ctrl.Result, error) { + log := r.log.WithValues("rid", utils.RandString(5)) + ctx = context.WithValue(ctx, helpers.ErrType("log"), &log) + pool := crd.NamespacePool{} if err := r.client.Get(ctx, req.NamespacedName, &pool); err != nil { - r.log.Error(err, fmt.Sprintf("cannot retrieve [%s] pool resource", pool.Name)) + log.Error(err, fmt.Sprintf("cannot retrieve [%s] pool resource", pool.Name)) return ctrl.Result{Requeue: true}, err } errNamespaceList, err := r.getPoolStatus(ctx, &pool) if err != nil { - r.log.Error(err, "unable to get status of owned namespaces") + log.Error(err, "unable to get status of owned namespaces") return ctrl.Result{Requeue: true}, err } if len(errNamespaceList) > 0 { - r.log.Info(fmt.Sprintf("[%d] namespaces in error state are queued for deletion", len(errNamespaceList))) + log.Info(fmt.Sprintf("[%d] namespaces in error state are queued for deletion", len(errNamespaceList))) err = r.deleteErrorNamespaces(ctx, errNamespaceList) if err != nil { r.log.Error(err, "Unable to delete namespaces in error state") @@ -68,7 +72,7 @@ func (r *NamespacePoolReconciler) Reconcile(ctx context.Context, req ctrl.Reques } } - r.log.Info(fmt.Sprintf("[%s] pool status", pool.Name), + log.Info(fmt.Sprintf("[%s] pool status", pool.Name), "ready", pool.Status.Ready, "creating", pool.Status.Creating, "reserved", pool.Status.Reserved) @@ -76,14 +80,14 @@ func (r *NamespacePoolReconciler) Reconcile(ctx context.Context, req ctrl.Reques quantityOfNamespaces := r.getNamespaceQuantityDelta(pool) if quantityOfNamespaces > 0 { - r.log.Info(fmt.Sprintf("filling [%s] pool with [%d] namespace(s)", pool.Name, quantityOfNamespaces)) + log.Info(fmt.Sprintf("filling [%s] pool with [%d] namespace(s)", pool.Name, quantityOfNamespaces)) err := r.increaseReadyNamespacesQueue(ctx, pool, quantityOfNamespaces) if err != nil { - r.log.Error(err, fmt.Sprintf("unable to create more namespaces for [%s] pool.", pool.Name)) + log.Error(err, fmt.Sprintf("unable to create more namespaces for [%s] pool.", pool.Name)) return ctrl.Result{Requeue: true}, err } } else if quantityOfNamespaces < 0 { - r.log.Info(fmt.Sprintf("excess number of ready namespaces in [%s] pool detected, removing [%d] namespace(s)", pool.Name, (quantityOfNamespaces * -1))) + log.Info(fmt.Sprintf("excess number of ready namespaces in [%s] pool detected, removing [%d] namespace(s)", pool.Name, (quantityOfNamespaces * -1))) err := r.decreaseReadyNamespacesQueue(ctx, pool.Name, quantityOfNamespaces) if err != nil { r.log.Error(err, fmt.Sprintf("unable to delete excess namespaces for [%s] pool.", pool.Name)) @@ -92,7 +96,7 @@ func (r *NamespacePoolReconciler) Reconcile(ctx context.Context, req ctrl.Reques } if err := r.client.Status().Update(ctx, &pool); err != nil { - r.log.Error(err, fmt.Sprintf("cannot update [%s] pool status", pool.Name)) + log.Error(err, fmt.Sprintf("cannot update [%s] pool status", pool.Name)) return ctrl.Result{}, err } diff --git a/controllers/cloud.redhat.com/namespacereservation_controller.go b/controllers/cloud.redhat.com/namespacereservation_controller.go index 6da7bd26..52d90d34 100644 --- a/controllers/cloud.redhat.com/namespacereservation_controller.go +++ b/controllers/cloud.redhat.com/namespacereservation_controller.go @@ -24,6 +24,7 @@ import ( crd "github.com/RedHatInsights/ephemeral-namespace-operator/apis/cloud.redhat.com/v1alpha1" "github.com/RedHatInsights/ephemeral-namespace-operator/controllers/cloud.redhat.com/helpers" + "github.com/RedHatInsights/rhc-osdk-utils/utils" "github.com/go-logr/logr" core "k8s.io/api/core/v1" rbac "k8s.io/api/rbac/v1" @@ -60,6 +61,9 @@ type NamespaceReservationReconciler struct { //+kubebuilder:rbac:groups=rbac.authorization.k8s.io,resources=rolebindings;roles,verbs=get;list;watch;create;update;patch;delete func (r *NamespaceReservationReconciler) Reconcile(ctx context.Context, req ctrl.Request) (ctrl.Result, error) { + log := r.log.WithValues("rid", utils.RandString(5)) + ctx = context.WithValue(ctx, helpers.ErrType("log"), &log) + // Fetch the reservation res := crd.NamespaceReservation{} if err := r.client.Get(ctx, req.NamespacedName, &res); err != nil { @@ -67,7 +71,7 @@ func (r *NamespaceReservationReconciler) Reconcile(ctx context.Context, req ctrl // Must have been deleted return ctrl.Result{}, nil } - r.log.Error(err, "Reservation Not Found") + log.Error(err, "Reservation Not Found") return ctrl.Result{}, err } @@ -81,7 +85,7 @@ func (r *NamespaceReservationReconciler) Reconcile(ctx context.Context, req ctrl switch res.Status.State { case "active": - r.log.Info("Reconciling active reservation", "name", res.Name, "namespace", res.Status.Namespace) + log.Info("Reconciling active reservation", "name", res.Name, "namespace", res.Status.Namespace) expirationTS, err := getExpirationTime(&res) if err != nil { r.log.Error(err, "Could not get expiration time for reservation", "name", res.Name) @@ -92,7 +96,7 @@ func (r *NamespaceReservationReconciler) Reconcile(ctx context.Context, req ctrl r.poller.activeReservations[res.Name] = expirationTS if err := r.client.Status().Update(ctx, &res); err != nil { - r.log.Error(err, "Cannot update reservation status", "name", res.Name) + log.Error(err, "Cannot update reservation status", "name", res.Name) return ctrl.Result{}, err } @@ -101,15 +105,15 @@ func (r *NamespaceReservationReconciler) Reconcile(ctx context.Context, req ctrl return ctrl.Result{}, nil case "waiting": - r.log.Info("Reconciling waiting reservation", "name", res.Name) + log.Info("Reconciling waiting reservation", "name", res.Name) expirationTS, err := getExpirationTime(&res) if err != nil { - r.log.Error(err, "Could not get expiration time for reservation", "name", res.Name) + log.Error(err, "Could not get expiration time for reservation", "name", res.Name) return ctrl.Result{}, err } if r.poller.namespaceIsExpired(expirationTS) { if err := r.client.Delete(ctx, &res); err != nil { - r.log.Error(err, "Unable to delete waiting reservation", "res-name", res.Name) + log.Error(err, "Unable to delete waiting reservation", "res-name", res.Name) } return ctrl.Result{}, nil } @@ -117,32 +121,32 @@ func (r *NamespaceReservationReconciler) Reconcile(ctx context.Context, req ctrl default: // if no, requeue and wait for pool to populate - r.log.Info("Reconciling reservation", "name", res.Name) - r.log.Info(fmt.Sprintf("Checking %s pool for ready namespaces", res.Status.Pool), "name", res.Name) + log.Info("Reconciling reservation", "name", res.Name) + log.Info(fmt.Sprintf("Checking %s pool for ready namespaces", res.Status.Pool), "name", res.Name) expirationTS, err := getExpirationTime(&res) if err != nil { - r.log.Error(err, "Could not set expiration time on reservation. Deleting", "res-name", res.Name) + log.Error(err, "Could not set expiration time on reservation. Deleting", "res-name", res.Name) if err := r.client.Delete(ctx, &res); err != nil { - r.log.Error(err, "cannot delete resource - aborting delete", "name", res.Name) + log.Error(err, "cannot delete resource - aborting delete", "name", res.Name) } return ctrl.Result{}, err } nsList, err := helpers.GetReadyNamespaces(ctx, r.client, res.Status.Pool) if err != nil { - r.log.Error(err, fmt.Sprintf("unable to retrieve list of namespaces from '%s' pool", res.Status.Pool), "res-name", res.Name) + log.Error(err, fmt.Sprintf("unable to retrieve list of namespaces from '%s' pool", res.Status.Pool), "res-name", res.Name) return ctrl.Result{}, err } if len(nsList) < 1 { - r.log.Info(fmt.Sprintf("requeue to wait for namespace population from '%s' pool", res.Status.Pool), "name", res.Name) + log.Info(fmt.Sprintf("requeue to wait for namespace population from '%s' pool", res.Status.Pool), "name", res.Name) if res.Status.State == "" { res.Status.State = "waiting" res.Status.Expiration = expirationTS err := r.client.Status().Update(ctx, &res) if err != nil { - r.log.Error(err, "cannot update status", "name", res.Name) + log.Error(err, "cannot update status", "name", res.Name) return ctrl.Result{}, err } } @@ -151,13 +155,13 @@ func (r *NamespaceReservationReconciler) Reconcile(ctx context.Context, req ctrl // Check to see if there's an error with the Get readyNsName := nsList[0].Name - r.log.Info(fmt.Sprintf("Found namespace in '%s' pool; verifying ready status", res.Status.Pool)) + log.Info(fmt.Sprintf("Found namespace in '%s' pool; verifying ready status", res.Status.Pool)) // Verify that the ClowdEnv has been set up for the requested namespace if err := r.verifyClowdEnvForReadyNs(ctx, readyNsName); err != nil { - r.log.Error(err, err.Error(), "namespace", readyNsName) + log.Error(err, err.Error(), "namespace", readyNsName) if err := helpers.UpdateAnnotations(ctx, r.client, readyNsName, helpers.AnnotationEnvError.ToMap()); err != nil { - r.log.Error(err, fmt.Sprintf("unable to update annotations for unready namespace in '%s' pool", res.Status.Pool), "namespace", readyNsName) + log.Error(err, fmt.Sprintf("unable to update annotations for unready namespace in '%s' pool", res.Status.Pool), "namespace", readyNsName) return ctrl.Result{Requeue: true}, err } return ctrl.Result{Requeue: true}, err @@ -165,7 +169,7 @@ func (r *NamespaceReservationReconciler) Reconcile(ctx context.Context, req ctrl // Resolve the requested namespace and remove it from the pool if err := r.reserveNamespace(ctx, readyNsName, &res); err != nil { - r.log.Error(err, fmt.Sprintf("could not reserve namespace from '%s' pool", res.Status.Pool), "namespace", readyNsName) + log.Error(err, fmt.Sprintf("could not reserve namespace from '%s' pool", res.Status.Pool), "namespace", readyNsName) totalFailedPoolReservationsCountMetrics.With(prometheus.Labels{"pool": res.Spec.Pool}).Inc() @@ -179,8 +183,8 @@ func (r *NamespaceReservationReconciler) Reconcile(ctx context.Context, req ctrl r.poller.activeReservations[res.Name] = expirationTS - r.log.Info("updating NamespaceReservation status") - r.log.Info("reservation details", + log.Info("updating NamespaceReservation status") + log.Info("reservation details", "res-name", res.Name, "res-uuid", res.ObjectMeta.UID, "created", res.ObjectMeta.CreationTimestamp, @@ -188,13 +192,13 @@ func (r *NamespaceReservationReconciler) Reconcile(ctx context.Context, req ctrl "status", res.Status, ) if err := r.client.Status().Update(ctx, &res); err != nil { - r.log.Error(err, "cannot update status") + log.Error(err, "cannot update status") return ctrl.Result{}, err } duration, err := parseDurationTime(*res.Spec.Duration) if err != nil { - r.log.Error(err, "cannot parse duration") + log.Error(err, "cannot parse duration") return ctrl.Result{}, err }