From 727f769826ec038902c686df355de8bac695fec0 Mon Sep 17 00:00:00 2001 From: Nir Magnezi Date: Sun, 23 May 2021 17:07:54 +0300 Subject: [PATCH] MGMT-6455 KubeAPI Controllers Debuggability: Add Logger Fields This change adds logger fields to controllers to specify the resource name and namespace that is being reconciled. Additionally, in a case that context does not have a request-id, we'll generate one to track it down both in controllers and the backend. Lastly, I added a log indicating that a reconcile iteration has ended. --- cmd/operator/main.go | 5 +- .../controllers/agent_controller.go | 88 ++++--- .../agentserviceconfig_controller.go | 102 ++++---- .../agentserviceconfig_controller_test.go | 37 +-- .../controllers/bmh_agent_controller.go | 91 ++++--- .../clusterdeployments_controller.go | 238 ++++++++++-------- internal/controller/controllers/common.go | 13 +- .../controllers/infraenv_controller.go | 89 ++++--- 8 files changed, 379 insertions(+), 284 deletions(-) diff --git a/cmd/operator/main.go b/cmd/operator/main.go index 1aeb49c170f..df9480abaad 100644 --- a/cmd/operator/main.go +++ b/cmd/operator/main.go @@ -24,8 +24,9 @@ import ( routev1 "github.com/openshift/api/route/v1" aiv1beta1 "github.com/openshift/assisted-service/internal/controller/api/v1beta1" - controllers "github.com/openshift/assisted-service/internal/controller/controllers" + "github.com/openshift/assisted-service/internal/controller/controllers" "github.com/openshift/assisted-service/models" + "github.com/sirupsen/logrus" "k8s.io/apimachinery/pkg/runtime" utilruntime "k8s.io/apimachinery/pkg/util/runtime" clientgoscheme "k8s.io/client-go/kubernetes/scheme" @@ -106,7 +107,7 @@ func main() { if err = (&controllers.AgentServiceConfigReconciler{ Client: mgr.GetClient(), - Log: ctrl.Log.WithName("controllers").WithName("AgentServiceConfig"), + Log: logrus.New(), Scheme: mgr.GetScheme(), Recorder: mgr.GetEventRecorderFor("agentserviceconfig-controller"), Namespace: ns, diff --git a/internal/controller/controllers/agent_controller.go b/internal/controller/controllers/agent_controller.go index b5dfed423a2..67c7f958cc8 100644 --- a/internal/controller/controllers/agent_controller.go +++ b/internal/controller/controllers/agent_controller.go @@ -31,6 +31,7 @@ import ( aiv1beta1 "github.com/openshift/assisted-service/internal/controller/api/v1beta1" "github.com/openshift/assisted-service/internal/host" "github.com/openshift/assisted-service/models" + logutil "github.com/openshift/assisted-service/pkg/log" "github.com/openshift/assisted-service/restapi/operations/installer" conditionsv1 "github.com/openshift/custom-resource-status/conditions/v1" hivev1 "github.com/openshift/hive/apis/hive/v1" @@ -66,18 +67,29 @@ type AgentReconciler struct { // +kubebuilder:rbac:groups=agent-install.openshift.io,resources=agents/status,verbs=get;update;patch // +kubebuilder:rbac:groups=agent-install.openshift.io,resources=agents/ai-deprovision,verbs=update -func (r *AgentReconciler) Reconcile(ctx context.Context, req ctrl.Request) (ctrl.Result, error) { - r.Log.Infof("Reconcile has been called for Agent name=%s namespace=%s", req.Name, req.Namespace) +func (r *AgentReconciler) Reconcile(origCtx context.Context, req ctrl.Request) (ctrl.Result, error) { + ctx := addRequestIdIfNeeded(origCtx) + log := logutil.FromContext(ctx, r.Log).WithFields( + logrus.Fields{ + "agent": req.Name, + "agent_namespace": req.Namespace, + }) + + defer func() { + log.Info("Agent Reconcile ended") + }() + + log.Info("Agent Reconcile started") agent := &aiv1beta1.Agent{} err := r.Get(ctx, req.NamespacedName, agent) if err != nil { - r.Log.WithError(err).Errorf("Failed to get resource %s", req.NamespacedName) + log.WithError(err).Errorf("Failed to get resource %s", req.NamespacedName) return ctrl.Result{}, client.IgnoreNotFound(err) } if agent.Spec.ClusterDeploymentName == nil { - r.Log.Debugf("ClusterDeploymentName not set in Agent %s. Skipping Reconcile", agent.Name) + log.Debugf("ClusterDeploymentName not set in Agent %s. Skipping Reconcile", agent.Name) return ctrl.Result{Requeue: false}, nil } @@ -86,22 +98,22 @@ func (r *AgentReconciler) Reconcile(ctx context.Context, req ctrl.Request) (ctrl if !funk.ContainsString(agent.GetFinalizers(), AgentFinalizerName) { controllerutil.AddFinalizer(agent, AgentFinalizerName) if err = r.Update(ctx, agent); err != nil { - r.Log.WithError(err).Errorf("failed to add finalizer %s to resource %s %s", AgentFinalizerName, agent.Name, agent.Namespace) + log.WithError(err).Errorf("failed to add finalizer %s to resource %s %s", AgentFinalizerName, agent.Name, agent.Namespace) return ctrl.Result{Requeue: true}, err } } } else { // agent is being deleted if funk.ContainsString(agent.GetFinalizers(), AgentFinalizerName) { // deletion finalizer found, deregister the backend host and delete the agent - reply, cleanUpErr := r.deregisterHostIfNeeded(ctx, req.NamespacedName) + reply, cleanUpErr := r.deregisterHostIfNeeded(ctx, log, req.NamespacedName) if cleanUpErr != nil { - r.Log.WithError(cleanUpErr).Errorf("failed to run pre-deletion cleanup for finalizer %s on resource %s %s", AgentFinalizerName, agent.Name, agent.Namespace) + log.WithError(cleanUpErr).Errorf("failed to run pre-deletion cleanup for finalizer %s on resource %s %s", AgentFinalizerName, agent.Name, agent.Namespace) return reply, err } // remove our finalizer from the list and update it. controllerutil.RemoveFinalizer(agent, AgentFinalizerName) if err = r.Update(ctx, agent); err != nil { - r.Log.WithError(err).Errorf("failed to remove finalizer %s from resource %s %s", AgentFinalizerName, agent.Name, agent.Namespace) + log.WithError(err).Errorf("failed to remove finalizer %s from resource %s %s", AgentFinalizerName, agent.Name, agent.Namespace) return ctrl.Result{Requeue: true}, err } } @@ -119,12 +131,12 @@ func (r *AgentReconciler) Reconcile(ctx context.Context, req ctrl.Request) (ctrl if err = r.Get(ctx, kubeKey, clusterDeployment); err != nil { if k8serrors.IsNotFound(err) { // Delete the agent, using a finalizer with pre-delete to deregister the host. - return r.deleteAgent(ctx, req.NamespacedName) + return r.deleteAgent(ctx, log, req.NamespacedName) } errMsg := fmt.Sprintf("failed to get clusterDeployment with name %s in namespace %s", agent.Spec.ClusterDeploymentName.Name, agent.Spec.ClusterDeploymentName.Namespace) // Update that we failed to retrieve the clusterDeployment - return r.updateStatus(ctx, agent, nil, errors.Wrapf(err, errMsg), !k8serrors.IsNotFound(err)) + return r.updateStatus(ctx, log, agent, nil, errors.Wrapf(err, errMsg), !k8serrors.IsNotFound(err)) } // Retrieve cluster by ClusterDeploymentName from the database @@ -132,10 +144,10 @@ func (r *AgentReconciler) Reconcile(ctx context.Context, req ctrl.Request) (ctrl if err != nil { if errors.Is(err, gorm.ErrRecordNotFound) { // Delete the agent, using a finalizer with pre-delete to deregister the host. - return r.deleteAgent(ctx, req.NamespacedName) + return r.deleteAgent(ctx, log, req.NamespacedName) } // Update that we failed to retrieve the cluster from the database - return r.updateStatus(ctx, agent, nil, err, !errors.Is(err, gorm.ErrRecordNotFound)) + return r.updateStatus(ctx, log, agent, nil, err, !errors.Is(err, gorm.ErrRecordNotFound)) } //Retrieve host from cluster @@ -143,24 +155,24 @@ func (r *AgentReconciler) Reconcile(ctx context.Context, req ctrl.Request) (ctrl if host == nil { // Host is not a part of the cluster, which may happen with newly created day2 clusters. // Delete the agent, using a finalizer with pre-delete to deregister the host. - return r.deleteAgent(ctx, req.NamespacedName) + return r.deleteAgent(ctx, log, req.NamespacedName) } // check for updates from user, compare spec and update if needed - err = r.updateIfNeeded(ctx, agent, cluster) + err = r.updateIfNeeded(ctx, log, agent, cluster) if err != nil { - return r.updateStatus(ctx, agent, host, err, !IsUserError(err)) + return r.updateStatus(ctx, log, agent, host, err, !IsUserError(err)) } - err = r.updateInventory(host, agent) + err = r.updateInventory(log, host, agent) if err != nil { - return r.updateStatus(ctx, agent, host, err, true) + return r.updateStatus(ctx, log, agent, host, err, true) } - return r.updateStatus(ctx, agent, host, nil, false) + return r.updateStatus(ctx, log, agent, host, nil, false) } -func (r *AgentReconciler) deleteAgent(ctx context.Context, agent types.NamespacedName) (ctrl.Result, error) { +func (r *AgentReconciler) deleteAgent(ctx context.Context, log logrus.FieldLogger, agent types.NamespacedName) (ctrl.Result, error) { agentToDelete := &aiv1beta1.Agent{ ObjectMeta: metav1.ObjectMeta{ Name: agent.Name, @@ -168,13 +180,13 @@ func (r *AgentReconciler) deleteAgent(ctx context.Context, agent types.Namespace }, } if delErr := r.Client.Delete(ctx, agentToDelete); delErr != nil { - r.Log.WithError(delErr).Errorf("Failed to delete resource %s %s", agent.Name, agent.Namespace) + log.WithError(delErr).Errorf("Failed to delete resource %s %s", agent.Name, agent.Namespace) return ctrl.Result{Requeue: true}, delErr } return ctrl.Result{}, nil } -func (r *AgentReconciler) deregisterHostIfNeeded(ctx context.Context, key types.NamespacedName) (ctrl.Result, error) { +func (r *AgentReconciler) deregisterHostIfNeeded(ctx context.Context, log logrus.FieldLogger, key types.NamespacedName) (ctrl.Result, error) { buildReply := func(err error) (ctrl.Result, error) { reply := ctrl.Result{} @@ -183,7 +195,7 @@ func (r *AgentReconciler) deregisterHostIfNeeded(ctx context.Context, key types. } reply.RequeueAfter = defaultRequeueAfterOnError err = errors.Wrapf(err, "failed to deregister host: %s", key.Name) - r.Log.Error(err) + log.Error(err) return reply, err } @@ -212,7 +224,7 @@ func (r *AgentReconciler) deregisterHostIfNeeded(ctx context.Context, key types. } } - r.Log.Infof("Host resource deleted, Unregistered host: %s", h.ID.String()) + log.Infof("Host resource deleted, Unregistered host: %s", h.ID.String()) return buildReply(nil) } @@ -220,7 +232,7 @@ func (r *AgentReconciler) deregisterHostIfNeeded(ctx context.Context, key types. // updateStatus is updating all the Agent Conditions. // In case that an error has occured when trying to sync the Spec, the error (syncErr) is presented in SpecSyncedCondition. // Internal bool differentiate between backend server error (internal HTTP 5XX) and user input error (HTTP 4XXX) -func (r *AgentReconciler) updateStatus(ctx context.Context, agent *aiv1beta1.Agent, h *models.Host, syncErr error, internal bool) (ctrl.Result, error) { +func (r *AgentReconciler) updateStatus(ctx context.Context, log logrus.FieldLogger, agent *aiv1beta1.Agent, h *models.Host, syncErr error, internal bool) (ctrl.Result, error) { specSynced(agent, syncErr, internal) @@ -234,7 +246,7 @@ func (r *AgentReconciler) updateStatus(ctx context.Context, agent *aiv1beta1.Age setConditionsUnknown(agent) } if updateErr := r.Status().Update(ctx, agent); updateErr != nil { - r.Log.WithError(updateErr).Error("failed to update agent Status") + log.WithError(updateErr).Error("failed to update agent Status") return ctrl.Result{Requeue: true}, nil } if internal { @@ -299,10 +311,10 @@ func specSynced(agent *aiv1beta1.Agent, syncErr error, internal bool) { }) } -func (r *AgentReconciler) updateInstallerArgs(ctx context.Context, c *common.Cluster, host *common.Host, agent *aiv1beta1.Agent) error { +func (r *AgentReconciler) updateInstallerArgs(ctx context.Context, log logrus.FieldLogger, c *common.Cluster, host *common.Host, agent *aiv1beta1.Agent) error { if agent.Spec.InstallerArgs == host.InstallerArgs { - r.Log.Debugf("Nothing to update, installer args were already set") + log.Debugf("Nothing to update, installer args were already set") return nil } @@ -316,7 +328,7 @@ func (r *AgentReconciler) updateInstallerArgs(ctx context.Context, c *common.Clu err := json.Unmarshal([]byte(agent.Spec.InstallerArgs), &agentSpecInstallerArgs.Args) if err != nil { msg := fmt.Sprintf("Fail to unmarshal installer args for host %s in cluster %s", agent.Name, c.Name) - r.Log.WithError(err).Errorf(msg) + log.WithError(err).Errorf(msg) return common.NewApiError(http.StatusBadRequest, errors.Wrapf(err, msg)) } } @@ -325,7 +337,7 @@ func (r *AgentReconciler) updateInstallerArgs(ctx context.Context, c *common.Clu argsBytes, _ := json.Marshal(agentSpecInstallerArgs.Args) // we need to validate if the equal one more after marshalling if string(argsBytes) == host.InstallerArgs { - r.Log.Debugf("Nothing to update, installer args were already set") + log.Debugf("Nothing to update, installer args were already set") return nil } @@ -476,9 +488,9 @@ func readyForInstallation(agent *aiv1beta1.Agent, status string) { }) } -func (r *AgentReconciler) updateInventory(host *models.Host, agent *aiv1beta1.Agent) error { +func (r *AgentReconciler) updateInventory(log logrus.FieldLogger, host *models.Host, agent *aiv1beta1.Agent) error { if host.Inventory == "" { - r.Log.Debugf("Skip update inventory: Host %s inventory not set", agent.Name) + log.Debugf("Skip update inventory: Host %s inventory not set", agent.Name) return nil } var inventory models.Inventory @@ -582,9 +594,9 @@ func (r *AgentReconciler) updateInventory(host *models.Host, agent *aiv1beta1.Ag return nil } -func (r *AgentReconciler) updateHostIgnition(ctx context.Context, c *common.Cluster, host *common.Host, agent *aiv1beta1.Agent) error { +func (r *AgentReconciler) updateHostIgnition(ctx context.Context, log logrus.FieldLogger, c *common.Cluster, host *common.Host, agent *aiv1beta1.Agent) error { if agent.Spec.IgnitionConfigOverrides == host.IgnitionConfigOverrides { - r.Log.Debugf("Nothing to update, ignition config override was already set") + log.Debugf("Nothing to update, ignition config override was already set") return nil } agentHostIgnitionParams := models.HostIgnitionParams{Config: ""} @@ -601,11 +613,11 @@ func (r *AgentReconciler) updateHostIgnition(ctx context.Context, c *common.Clus return err } -func (r *AgentReconciler) updateIfNeeded(ctx context.Context, agent *aiv1beta1.Agent, c *common.Cluster) error { +func (r *AgentReconciler) updateIfNeeded(ctx context.Context, log logrus.FieldLogger, agent *aiv1beta1.Agent, c *common.Cluster) error { spec := agent.Spec host := getHostFromCluster(c, agent.Name) if host == nil { - r.Log.Errorf("Host %s not found in cluster %s", agent.Name, c.Name) + log.Errorf("Host %s not found in cluster %s", agent.Name, c.Name) return errors.New("Host not found in cluster") } @@ -627,7 +639,7 @@ func (r *AgentReconciler) updateIfNeeded(ctx context.Context, agent *aiv1beta1.A } } - err = r.updateInstallerArgs(ctx, c, internalHost, agent) + err = r.updateInstallerArgs(ctx, log, c, internalHost, agent) if err != nil { if errors.Is(err, gorm.ErrRecordNotFound) { err = common.NewApiError(http.StatusNotFound, err) @@ -635,7 +647,7 @@ func (r *AgentReconciler) updateIfNeeded(ctx context.Context, agent *aiv1beta1.A return err } - err = r.updateHostIgnition(ctx, c, internalHost, agent) + err = r.updateHostIgnition(ctx, log, c, internalHost, agent) if err != nil { if errors.Is(err, gorm.ErrRecordNotFound) { err = common.NewApiError(http.StatusNotFound, err) @@ -699,7 +711,7 @@ func (r *AgentReconciler) updateIfNeeded(ctx context.Context, agent *aiv1beta1.A return err } - r.Log.Infof("Updated Agent spec %s %s", agent.Name, agent.Namespace) + log.Infof("Updated Agent spec %s %s", agent.Name, agent.Namespace) return nil } diff --git a/internal/controller/controllers/agentserviceconfig_controller.go b/internal/controller/controllers/agentserviceconfig_controller.go index 262cf80b462..334251bceff 100644 --- a/internal/controller/controllers/agentserviceconfig_controller.go +++ b/internal/controller/controllers/agentserviceconfig_controller.go @@ -23,7 +23,6 @@ import ( "net/url" "strconv" - "github.com/go-logr/logr" "github.com/go-openapi/swag" "github.com/hashicorp/go-version" routev1 "github.com/openshift/api/route/v1" @@ -31,7 +30,9 @@ import ( aiv1beta1 "github.com/openshift/assisted-service/internal/controller/api/v1beta1" "github.com/openshift/assisted-service/internal/gencrypto" "github.com/openshift/assisted-service/models" + logutil "github.com/openshift/assisted-service/pkg/log" conditionsv1 "github.com/openshift/custom-resource-status/conditions/v1" + "github.com/sirupsen/logrus" appsv1 "k8s.io/api/apps/v1" corev1 "k8s.io/api/core/v1" "k8s.io/apimachinery/pkg/api/errors" @@ -73,7 +74,7 @@ const ( // AgentServiceConfigReconciler reconciles a AgentServiceConfig object type AgentServiceConfigReconciler struct { client.Client - Log logr.Logger + Log logrus.FieldLogger Scheme *runtime.Scheme Recorder record.EventRecorder @@ -92,7 +93,20 @@ type AgentServiceConfigReconciler struct { // +kubebuilder:rbac:groups=route.openshift.io,resources=routes,verbs=get;list;watch;create;update;patch;delete // +kubebuilder:rbac:groups="",resources=events,verbs=create;patch -func (r *AgentServiceConfigReconciler) Reconcile(ctx context.Context, req ctrl.Request) (ctrl.Result, error) { +func (r *AgentServiceConfigReconciler) Reconcile(origCtx context.Context, req ctrl.Request) (ctrl.Result, error) { + ctx := addRequestIdIfNeeded(origCtx) + log := logutil.FromContext(ctx, r.Log).WithFields( + logrus.Fields{ + "agent_service_config": req.Name, + "agent_service_config_namespace": req.Namespace, + }) + + defer func() { + log.Info("AgentServiceConfig Reconcile ended") + }() + + log.Info("AgentServiceConfig Reconcile started") + instance := &aiv1beta1.AgentServiceConfig{} // NOTE: ignoring the Namespace that seems to get set on request when syncing on namespaced objects @@ -104,7 +118,7 @@ func (r *AgentServiceConfigReconciler) Reconcile(ctx context.Context, req ctrl.R // Return and don't requeue return reconcile.Result{}, nil } - r.Log.Error(err, "Failed to get resource", req.NamespacedName) + log.Error(err, "Failed to get resource", req.NamespacedName) return ctrl.Result{}, err } @@ -113,12 +127,12 @@ func (r *AgentServiceConfigReconciler) Reconcile(ctx context.Context, req ctrl.R if instance.Name != agentServiceConfigName { reason := fmt.Sprintf("Invalid name (%s)", instance.Name) msg := fmt.Sprintf("Only one AgentServiceConfig supported per cluster and must be named '%s'", agentServiceConfigName) - r.Log.Info(fmt.Sprintf("%s: %s", reason, msg), req.NamespacedName) + log.Info(fmt.Sprintf("%s: %s", reason, msg), req.NamespacedName) r.Recorder.Event(instance, "Warning", reason, msg) return reconcile.Result{}, nil } - for _, f := range []func(context.Context, *aiv1beta1.AgentServiceConfig) error{ + for _, f := range []func(context.Context, logrus.FieldLogger, *aiv1beta1.AgentServiceConfig) error{ r.ensureFilesystemStorage, r.ensureDatabaseStorage, r.ensureAgentService, @@ -129,11 +143,11 @@ func (r *AgentServiceConfigReconciler) Reconcile(ctx context.Context, req ctrl.R r.ensureAssistedCM, r.ensureAssistedServiceDeployment, } { - err := f(ctx, instance) + err := f(ctx, log, instance) if err != nil { - r.Log.Error(err, "Failed reconcile") + log.Error(err, "Failed reconcile") if statusErr := r.Status().Update(ctx, instance); statusErr != nil { - r.Log.Error(err, "Failed to update status") + log.Error(err, "Failed to update status") return ctrl.Result{Requeue: true}, statusErr } return ctrl.Result{Requeue: true}, err @@ -150,7 +164,7 @@ func (r *AgentServiceConfigReconciler) Reconcile(ctx context.Context, req ctrl.R return ctrl.Result{}, r.Status().Update(ctx, instance) } -func (r *AgentServiceConfigReconciler) ensureFilesystemStorage(ctx context.Context, instance *aiv1beta1.AgentServiceConfig) error { +func (r *AgentServiceConfigReconciler) ensureFilesystemStorage(ctx context.Context, log logrus.FieldLogger, instance *aiv1beta1.AgentServiceConfig) error { pvc, mutateFn := r.newPVC(instance, serviceName, instance.Spec.FileSystemStorage) if result, err := controllerutil.CreateOrUpdate(ctx, r.Client, pvc, mutateFn); err != nil { @@ -162,12 +176,12 @@ func (r *AgentServiceConfigReconciler) ensureFilesystemStorage(ctx context.Conte }) return err } else if result != controllerutil.OperationResultNone { - r.Log.Info("Filesystem storage created") + log.Info("Filesystem storage created") } return nil } -func (r *AgentServiceConfigReconciler) ensureDatabaseStorage(ctx context.Context, instance *aiv1beta1.AgentServiceConfig) error { +func (r *AgentServiceConfigReconciler) ensureDatabaseStorage(ctx context.Context, log logrus.FieldLogger, instance *aiv1beta1.AgentServiceConfig) error { pvc, mutateFn := r.newPVC(instance, databaseName, instance.Spec.DatabaseStorage) if result, err := controllerutil.CreateOrUpdate(ctx, r.Client, pvc, mutateFn); err != nil { @@ -179,12 +193,12 @@ func (r *AgentServiceConfigReconciler) ensureDatabaseStorage(ctx context.Context }) return err } else if result != controllerutil.OperationResultNone { - r.Log.Info("Database storage created") + log.Info("Database storage created") } return nil } -func (r *AgentServiceConfigReconciler) ensureAgentService(ctx context.Context, instance *aiv1beta1.AgentServiceConfig) error { +func (r *AgentServiceConfigReconciler) ensureAgentService(ctx context.Context, log logrus.FieldLogger, instance *aiv1beta1.AgentServiceConfig) error { svc, mutateFn := r.newAgentService(instance) if result, err := controllerutil.CreateOrUpdate(ctx, r.Client, svc, mutateFn); err != nil { @@ -196,12 +210,12 @@ func (r *AgentServiceConfigReconciler) ensureAgentService(ctx context.Context, i }) return err } else if result != controllerutil.OperationResultNone { - r.Log.Info("Agent service created") + log.Info("Agent service created") } return nil } -func (r *AgentServiceConfigReconciler) ensureAgentRoute(ctx context.Context, instance *aiv1beta1.AgentServiceConfig) error { +func (r *AgentServiceConfigReconciler) ensureAgentRoute(ctx context.Context, log logrus.FieldLogger, instance *aiv1beta1.AgentServiceConfig) error { route, mutateFn := r.newAgentRoute(instance) if result, err := controllerutil.CreateOrUpdate(ctx, r.Client, route, mutateFn); err != nil { @@ -213,12 +227,12 @@ func (r *AgentServiceConfigReconciler) ensureAgentRoute(ctx context.Context, ins }) return err } else if result != controllerutil.OperationResultNone { - r.Log.Info("Agent route created") + log.Info("Agent route created") } return nil } -func (r *AgentServiceConfigReconciler) ensureAgentLocalAuthSecret(ctx context.Context, instance *aiv1beta1.AgentServiceConfig) error { +func (r *AgentServiceConfigReconciler) ensureAgentLocalAuthSecret(ctx context.Context, log logrus.FieldLogger, instance *aiv1beta1.AgentServiceConfig) error { secret, mutateFn, err := r.newAgentLocalAuthSecret(instance) if err != nil { conditionsv1.SetStatusConditionNoHeartbeat(&instance.Status.Conditions, conditionsv1.Condition{ @@ -241,15 +255,15 @@ func (r *AgentServiceConfigReconciler) ensureAgentLocalAuthSecret(ctx context.Co } else { switch result { case controllerutil.OperationResultCreated: - r.Log.Info("Agent local auth secret created") + log.Info("Agent local auth secret created") case controllerutil.OperationResultUpdated: - r.Log.Info("Agent local auth secret updated") + log.Info("Agent local auth secret updated") } } return nil } -func (r *AgentServiceConfigReconciler) ensurePostgresSecret(ctx context.Context, instance *aiv1beta1.AgentServiceConfig) error { +func (r *AgentServiceConfigReconciler) ensurePostgresSecret(ctx context.Context, log logrus.FieldLogger, instance *aiv1beta1.AgentServiceConfig) error { // TODO(djzager): using controllerutil.CreateOrUpdate is convenient but we may // want to consider simply creating the secret if we can't find instead of // generating a secret every reconcile. @@ -273,14 +287,14 @@ func (r *AgentServiceConfigReconciler) ensurePostgresSecret(ctx context.Context, }) return err } else if result != controllerutil.OperationResultNone { - r.Log.Info("Database secret created") + log.Info("Database secret created") } return nil } -func (r *AgentServiceConfigReconciler) ensureAssistedServiceDeployment(ctx context.Context, instance *aiv1beta1.AgentServiceConfig) error { +func (r *AgentServiceConfigReconciler) ensureAssistedServiceDeployment(ctx context.Context, log logrus.FieldLogger, instance *aiv1beta1.AgentServiceConfig) error { if instance.Spec.MirrorRegistryRef != nil { - err := r.validateMirrorRegistriesConfigMap(ctx, instance) + err := r.validateMirrorRegistriesConfigMap(ctx, log, instance) if err != nil { conditionsv1.SetStatusConditionNoHeartbeat(&instance.Status.Conditions, conditionsv1.Condition{ Type: aiv1beta1.ConditionReconcileCompleted, @@ -292,7 +306,7 @@ func (r *AgentServiceConfigReconciler) ensureAssistedServiceDeployment(ctx conte } } - deployment, mutateFn := r.newAssistedServiceDeployment(instance) + deployment, mutateFn := r.newAssistedServiceDeployment(log, instance) if result, err := controllerutil.CreateOrUpdate(ctx, r.Client, deployment, mutateFn); err != nil { conditionsv1.SetStatusConditionNoHeartbeat(&instance.Status.Conditions, conditionsv1.Condition{ @@ -303,16 +317,16 @@ func (r *AgentServiceConfigReconciler) ensureAssistedServiceDeployment(ctx conte }) return err } else if result != controllerutil.OperationResultNone { - r.Log.Info("Assisted service deployment created") + log.Info("Assisted service deployment created") } return nil } -func (r *AgentServiceConfigReconciler) ensureIngressCertCM(ctx context.Context, instance *aiv1beta1.AgentServiceConfig) error { +func (r *AgentServiceConfigReconciler) ensureIngressCertCM(ctx context.Context, log logrus.FieldLogger, instance *aiv1beta1.AgentServiceConfig) error { sourceCM := &corev1.ConfigMap{} if err := r.Get(ctx, types.NamespacedName{Name: defaultIngressCertCMName, Namespace: defaultIngressCertCMNamespace}, sourceCM); err != nil { - r.Log.Error(err, "Failed to get default ingress cert config map") + log.Error(err, "Failed to get default ingress cert config map") conditionsv1.SetStatusCondition(&instance.Status.Conditions, conditionsv1.Condition{ Type: aiv1beta1.ConditionReconcileCompleted, Status: corev1.ConditionFalse, @@ -333,12 +347,12 @@ func (r *AgentServiceConfigReconciler) ensureIngressCertCM(ctx context.Context, }) return err } else if result != controllerutil.OperationResultNone { - r.Log.Info("Ingress config map created") + log.Info("Ingress config map created") } return nil } -func (r *AgentServiceConfigReconciler) newAssistedCM(instance *aiv1beta1.AgentServiceConfig, serviceURL *url.URL) (*corev1.ConfigMap, controllerutil.MutateFn) { +func (r *AgentServiceConfigReconciler) newAssistedCM(log logrus.FieldLogger, instance *aiv1beta1.AgentServiceConfig, serviceURL *url.URL) (*corev1.ConfigMap, controllerutil.MutateFn) { cm := &corev1.ConfigMap{ ObjectMeta: metav1.ObjectMeta{ Name: serviceName, @@ -359,7 +373,7 @@ func (r *AgentServiceConfigReconciler) newAssistedCM(instance *aiv1beta1.AgentSe "CONTROLLER_IMAGE": ControllerImage(), "INSTALLER_IMAGE": InstallerImage(), "SELF_VERSION": ServiceImage(), - "OPENSHIFT_VERSIONS": r.getOpenshiftVersions(instance), + "OPENSHIFT_VERSIONS": r.getOpenshiftVersions(log, instance), "ISO_IMAGE_TYPE": "minimal-iso", "S3_USE_SSL": "false", @@ -401,7 +415,7 @@ func (r *AgentServiceConfigReconciler) newAssistedCM(instance *aiv1beta1.AgentSe return cm, mutateFn } -func (r *AgentServiceConfigReconciler) ensureAssistedCM(ctx context.Context, instance *aiv1beta1.AgentServiceConfig) error { +func (r *AgentServiceConfigReconciler) ensureAssistedCM(ctx context.Context, log logrus.FieldLogger, instance *aiv1beta1.AgentServiceConfig) error { // must have the route in order to populate SERVICE_BASE_URL for the service route := &routev1.Route{} err := r.Get(ctx, types.NamespacedName{Name: serviceName, Namespace: r.Namespace}, route) @@ -409,7 +423,7 @@ func (r *AgentServiceConfigReconciler) ensureAssistedCM(ctx context.Context, ins if err == nil { err = fmt.Errorf("Route's host is empty") } - r.Log.Info("Failed to get route or route's host is empty") + log.Info("Failed to get route or route's host is empty") conditionsv1.SetStatusConditionNoHeartbeat(&instance.Status.Conditions, conditionsv1.Condition{ Type: aiv1beta1.ConditionReconcileCompleted, Status: corev1.ConditionFalse, @@ -420,7 +434,7 @@ func (r *AgentServiceConfigReconciler) ensureAssistedCM(ctx context.Context, ins } serviceURL := &url.URL{Scheme: "https", Host: route.Spec.Host} - cm, mutateFn := r.newAssistedCM(instance, serviceURL) + cm, mutateFn := r.newAssistedCM(log, instance, serviceURL) if result, err := controllerutil.CreateOrUpdate(ctx, r.Client, cm, mutateFn); err != nil { conditionsv1.SetStatusCondition(&instance.Status.Conditions, conditionsv1.Condition{ @@ -431,22 +445,22 @@ func (r *AgentServiceConfigReconciler) ensureAssistedCM(ctx context.Context, ins }) return err } else if result != controllerutil.OperationResultNone { - r.Log.Info("Assisted settings config map created") + log.Info("Assisted settings config map created") } return nil } -func (r *AgentServiceConfigReconciler) validateMirrorRegistriesConfigMap(ctx context.Context, instance *aiv1beta1.AgentServiceConfig) error { +func (r *AgentServiceConfigReconciler) validateMirrorRegistriesConfigMap(ctx context.Context, log logrus.FieldLogger, instance *aiv1beta1.AgentServiceConfig) error { mirrorCM := &corev1.ConfigMap{} err := r.Get(ctx, types.NamespacedName{Name: instance.Spec.MirrorRegistryRef.Name, Namespace: r.Namespace}, mirrorCM) if err != nil { - r.Log.Info("Failed to get mirror registries ConfigMap") + log.Info("Failed to get mirror registries ConfigMap") return err } keysToValidate := []string{mirrorRegistryRefCertKey, mirrorRegistryRefRegistryConfKey} for _, key := range keysToValidate { if _, ok := mirrorCM.Data[key]; !ok { - r.Log.Info("mirror registries configmap %s does not contain key %s", instance.Spec.MirrorRegistryRef.Name, key) + log.Info("mirror registries configmap %s does not contain key %s", instance.Spec.MirrorRegistryRef.Name, key) err = fmt.Errorf("%s key missing in the mirrror registries configmap %s", key, instance.Spec.MirrorRegistryRef.Name) return err } @@ -668,7 +682,7 @@ func (r *AgentServiceConfigReconciler) newIngressCertCM(instance *aiv1beta1.Agen return cm, mutateFn } -func (r *AgentServiceConfigReconciler) newAssistedServiceDeployment(instance *aiv1beta1.AgentServiceConfig) (*appsv1.Deployment, controllerutil.MutateFn) { +func (r *AgentServiceConfigReconciler) newAssistedServiceDeployment(log logrus.FieldLogger, instance *aiv1beta1.AgentServiceConfig) (*appsv1.Deployment, controllerutil.MutateFn) { envSecrets := []corev1.EnvVar{ // database newSecretEnvVar("DB_HOST", "db.host", databaseName), @@ -696,7 +710,7 @@ func (r *AgentServiceConfigReconciler) newAssistedServiceDeployment(instance *ai annotations := instance.ObjectMeta.GetAnnotations() configmapName, ok := annotations[configmapAnnotation] if ok { - r.Log.Info("ConfigMap %v being used to configure assisted-service deployment", configmapName) + log.Info("ConfigMap %v being used to configure assisted-service deployment", configmapName) envFrom = append(envFrom, []corev1.EnvFromSource{ { ConfigMapRef: &corev1.ConfigMapEnvSource{ @@ -906,7 +920,7 @@ func (r *AgentServiceConfigReconciler) newAssistedServiceDeployment(instance *ai return deployment, mutateFn } -func (r *AgentServiceConfigReconciler) getOpenshiftVersions(instance *aiv1beta1.AgentServiceConfig) string { +func (r *AgentServiceConfigReconciler) getOpenshiftVersions(log logrus.FieldLogger, instance *aiv1beta1.AgentServiceConfig) string { if instance.Spec.OSImages == nil { return OpenshiftVersions() } @@ -915,7 +929,7 @@ func (r *AgentServiceConfigReconciler) getOpenshiftVersions(instance *aiv1beta1. for _, image := range instance.Spec.OSImages { v, err := version.NewVersion(image.OpenshiftVersion) if err != nil { - r.Log.Error(err, fmt.Sprintf("Problem parsing OpenShift version %v, skipping.", image.OpenshiftVersion)) + log.Error(err, fmt.Sprintf("Problem parsing OpenShift version %v, skipping.", image.OpenshiftVersion)) continue } @@ -933,13 +947,13 @@ func (r *AgentServiceConfigReconciler) getOpenshiftVersions(instance *aiv1beta1. } if len(openshiftVersions) == 0 { - r.Log.Info("No valid OS Image specified, returning default", "OpenShift Versions", OpenshiftVersions()) + log.Info("No valid OS Image specified, returning default", "OpenShift Versions", OpenshiftVersions()) return OpenshiftVersions() } encodedVersions, err := json.Marshal(openshiftVersions) if err != nil { - r.Log.Error(err, fmt.Sprintf("Problem marshaling versions (%v) to string, returning default %v", openshiftVersions, OpenshiftVersions())) + log.Error(err, fmt.Sprintf("Problem marshaling versions (%v) to string, returning default %v", openshiftVersions, OpenshiftVersions())) return OpenshiftVersions() } diff --git a/internal/controller/controllers/agentserviceconfig_controller_test.go b/internal/controller/controllers/agentserviceconfig_controller_test.go index 69a5d61c315..d2d6eedc153 100644 --- a/internal/controller/controllers/agentserviceconfig_controller_test.go +++ b/internal/controller/controllers/agentserviceconfig_controller_test.go @@ -10,6 +10,7 @@ import ( routev1 "github.com/openshift/api/route/v1" aiv1beta1 "github.com/openshift/assisted-service/internal/controller/api/v1beta1" "github.com/openshift/assisted-service/models" + "github.com/sirupsen/logrus" appsv1 "k8s.io/api/apps/v1" corev1 "k8s.io/api/core/v1" "k8s.io/apimachinery/pkg/api/resource" @@ -34,7 +35,7 @@ func newTestReconciler(initObjs ...runtime.Object) *AgentServiceConfigReconciler return &AgentServiceConfigReconciler{ Client: c, Scheme: scheme.Scheme, - Log: ctrl.Log.WithName("testLog"), + Log: logrus.New(), Namespace: testNamespace, } } @@ -91,6 +92,7 @@ var _ = Describe("ensureAgentRoute", func() { asc *aiv1beta1.AgentServiceConfig ascr *AgentServiceConfigReconciler ctx = context.Background() + log = logrus.New() ) BeforeEach(func() { @@ -104,7 +106,7 @@ var _ = Describe("ensureAgentRoute", func() { Expect(ascr.Client.Get(ctx, types.NamespacedName{Name: serviceName, Namespace: testNamespace}, found)).ToNot(Succeed()) - Expect(ascr.ensureAgentRoute(ctx, asc)).To(Succeed()) + Expect(ascr.ensureAgentRoute(ctx, log, asc)).To(Succeed()) Expect(ascr.Client.Get(ctx, types.NamespacedName{Name: serviceName, Namespace: testNamespace}, found)).To(Succeed()) @@ -118,7 +120,7 @@ var _ = Describe("ensureAgentRoute", func() { route.Spec.Host = routeHost Expect(ascr.Client.Create(ctx, route)).To(Succeed()) - Expect(ascr.ensureAgentRoute(ctx, asc)).To(Succeed()) + Expect(ascr.ensureAgentRoute(ctx, log, asc)).To(Succeed()) found := &routev1.Route{} Expect(ascr.Client.Get(ctx, types.NamespacedName{Name: serviceName, @@ -133,6 +135,7 @@ var _ = Describe("ensureAgentLocalAuthSecret", func() { asc *aiv1beta1.AgentServiceConfig ascr *AgentServiceConfigReconciler ctx = context.Background() + log = logrus.New() privateKey = "test-private-key" publicKey = "test-public-key" ) @@ -157,7 +160,7 @@ var _ = Describe("ensureAgentLocalAuthSecret", func() { } Expect(ascr.Client.Create(ctx, localAuthSecret)).To(Succeed()) - err := ascr.ensureAgentLocalAuthSecret(ctx, asc) + err := ascr.ensureAgentLocalAuthSecret(ctx, log, asc) Expect(err).To(BeNil()) found := &corev1.Secret{} @@ -171,7 +174,7 @@ var _ = Describe("ensureAgentLocalAuthSecret", func() { Context("with no existing local auth secret", func() { It("should create new keys and not overwrite them in subsequent reconciles", func() { - err := ascr.ensureAgentLocalAuthSecret(ctx, asc) + err := ascr.ensureAgentLocalAuthSecret(ctx, log, asc) Expect(err).To(BeNil()) found := &corev1.Secret{} @@ -186,7 +189,7 @@ var _ = Describe("ensureAgentLocalAuthSecret", func() { Expect(foundPublicKey).ToNot(Equal(publicKey)) Expect(foundPublicKey).ToNot(BeNil()) - err = ascr.ensureAgentLocalAuthSecret(ctx, asc) + err = ascr.ensureAgentLocalAuthSecret(ctx, log, asc) Expect(err).To(BeNil()) foundAfterNextEnsure := &corev1.Secret{} @@ -217,7 +220,7 @@ var _ = Describe("ensureAgentLocalAuthSecret", func() { } Expect(ascr.Client.Create(ctx, mirrorMap)).To(Succeed()) asc.Spec.MirrorRegistryRef = &corev1.LocalObjectReference{Name: "user-configmap"} - err := ascr.validateMirrorRegistriesConfigMap(ctx, asc) + err := ascr.validateMirrorRegistriesConfigMap(ctx, log, asc) Expect(err).To(BeNil()) }) It("invalid config map, keys", func() { @@ -237,7 +240,7 @@ var _ = Describe("ensureAgentLocalAuthSecret", func() { } Expect(ascr.Client.Create(ctx, mirrorMap)).To(Succeed()) asc.Spec.MirrorRegistryRef = &corev1.LocalObjectReference{Name: "user-configmap"} - err := ascr.validateMirrorRegistriesConfigMap(ctx, asc) + err := ascr.validateMirrorRegistriesConfigMap(ctx, log, asc) Expect(err).To(HaveOccurred()) }) @@ -249,6 +252,7 @@ var _ = Describe("ensureAssistedServiceDeployment", func() { asc *aiv1beta1.AgentServiceConfig ascr *AgentServiceConfigReconciler ctx = context.Background() + log = logrus.New() route = &routev1.Route{ ObjectMeta: metav1.ObjectMeta{ Name: serviceName, @@ -264,7 +268,7 @@ var _ = Describe("ensureAssistedServiceDeployment", func() { It("should not modify assisted-service deployment", func() { asc = newASCDefault() ascr = newTestReconciler(asc, route) - Expect(ascr.ensureAssistedServiceDeployment(ctx, asc)).To(Succeed()) + Expect(ascr.ensureAssistedServiceDeployment(ctx, log, asc)).To(Succeed()) found := &appsv1.Deployment{} Expect(ascr.Client.Get(ctx, types.NamespacedName{Name: serviceName, Namespace: testNamespace}, found)).To(Succeed()) @@ -284,7 +288,7 @@ var _ = Describe("ensureAssistedServiceDeployment", func() { It("should modify assisted-service deployment", func() { asc = newASCWithCMAnnotation() ascr = newTestReconciler(asc, route) - Expect(ascr.ensureAssistedServiceDeployment(ctx, asc)).To(Succeed()) + Expect(ascr.ensureAssistedServiceDeployment(ctx, log, asc)).To(Succeed()) found := &appsv1.Deployment{} Expect(ascr.Client.Get(ctx, types.NamespacedName{Name: serviceName, Namespace: testNamespace}, found)).To(Succeed()) @@ -319,6 +323,7 @@ var _ = Describe("getOpenshiftVersions", func() { var ( asc *aiv1beta1.AgentServiceConfig ascr *AgentServiceConfigReconciler + log = logrus.New() expectedEnv string ) @@ -333,28 +338,28 @@ var _ = Describe("getOpenshiftVersions", func() { asc = newASCDefault() ascr = newTestReconciler(asc) - Expect(ascr.getOpenshiftVersions(asc)).To(MatchJSON(expectedEnv)) + Expect(ascr.getOpenshiftVersions(log, asc)).To(MatchJSON(expectedEnv)) }) }) Context("with OpenShift versions specified", func() { It("should build OpenShift versions", func() { asc, expectedEnv = newASCWithOpenshiftVersions() ascr = newTestReconciler(asc) - Expect(ascr.getOpenshiftVersions(asc)).To(MatchJSON(expectedEnv)) + Expect(ascr.getOpenshiftVersions(log, asc)).To(MatchJSON(expectedEnv)) }) }) Context("with multiple OpenShift versions specified", func() { It("should build OpenShift versions with multiple keys", func() { asc, expectedEnv = newASCWithMultipleOpenshiftVersions() ascr = newTestReconciler(asc) - Expect(ascr.getOpenshiftVersions(asc)).To(MatchJSON(expectedEnv)) + Expect(ascr.getOpenshiftVersions(log, asc)).To(MatchJSON(expectedEnv)) }) }) Context("with duplicate OpenShift versions specified", func() { It("should take the last specified version", func() { asc, expectedEnv = newASCWithDuplicateOpenshiftVersions() ascr = newTestReconciler(asc) - Expect(ascr.getOpenshiftVersions(asc)).To(MatchJSON(expectedEnv)) + Expect(ascr.getOpenshiftVersions(log, asc)).To(MatchJSON(expectedEnv)) }) }) Context("with invalid OpenShift versions specified", func() { @@ -368,14 +373,14 @@ var _ = Describe("getOpenshiftVersions", func() { asc = newASCWithInvalidOpenshiftVersion() ascr = newTestReconciler(asc) - Expect(ascr.getOpenshiftVersions(asc)).To(MatchJSON(expectedEnv)) + Expect(ascr.getOpenshiftVersions(log, asc)).To(MatchJSON(expectedEnv)) }) }) Context("with OpenShift version x.y.z specified", func() { It("should only specify x.y", func() { asc, expectedEnv = newASCWithLongOpenshiftVersion() ascr = newTestReconciler(asc) - Expect(ascr.getOpenshiftVersions(asc)).To(MatchJSON(expectedEnv)) + Expect(ascr.getOpenshiftVersions(log, asc)).To(MatchJSON(expectedEnv)) }) }) }) diff --git a/internal/controller/controllers/bmh_agent_controller.go b/internal/controller/controllers/bmh_agent_controller.go index b7e64e95a20..37464f36291 100644 --- a/internal/controller/controllers/bmh_agent_controller.go +++ b/internal/controller/controllers/bmh_agent_controller.go @@ -27,6 +27,7 @@ import ( aiv1beta1 "github.com/openshift/assisted-service/internal/controller/api/v1beta1" "github.com/openshift/assisted-service/models" "github.com/openshift/assisted-service/pkg/conversions" + logutil "github.com/openshift/assisted-service/pkg/log" conditionsv1 "github.com/openshift/custom-resource-status/conditions/v1" hivev1 "github.com/openshift/hive/apis/hive/v1" machinev1beta1 "github.com/openshift/machine-api-operator/pkg/apis/machine/v1beta1" @@ -105,7 +106,19 @@ func (r reconcileError) Dirty() bool { // +kubebuilder:rbac:groups=metal3.io,resources=baremetalhosts,verbs=get;list;watch;update;patch -func (r *BMACReconciler) Reconcile(ctx context.Context, req ctrl.Request) (ctrl.Result, error) { +func (r *BMACReconciler) Reconcile(origCtx context.Context, req ctrl.Request) (ctrl.Result, error) { + ctx := addRequestIdIfNeeded(origCtx) + log := logutil.FromContext(ctx, r.Log).WithFields( + logrus.Fields{ + "bare_metal_host": req.Name, + "bare_metal_host_namespace": req.Namespace, + }) + + defer func() { + log.Info("BareMetalHost Reconcile ended") + }() + + log.Info("BareMetalHost Reconcile started") bmh := &bmh_v1alpha1.BareMetalHost{} if err := r.Get(ctx, req.NamespacedName, bmh); err != nil { @@ -116,12 +129,12 @@ func (r *BMACReconciler) Reconcile(ctx context.Context, req ctrl.Request) (ctrl. } // Let's reconcile the BMH - result := r.reconcileBMH(ctx, bmh) + result := r.reconcileBMH(ctx, log, bmh) if result.Dirty() { - r.Log.Debugf("Updating dirty BMH %v", bmh) + log.Debugf("Updating dirty BMH %v", bmh) err := r.Client.Update(ctx, bmh) if err != nil { - r.Log.WithError(err).Errorf("Error updating after BMH reconcile") + log.WithError(err).Errorf("Error updating after BMH reconcile") return reconcileError{err}.Result() } @@ -149,16 +162,16 @@ func (r *BMACReconciler) Reconcile(ctx context.Context, req ctrl.Request) (ctrl. if result.Dirty() { err := r.Client.Update(ctx, bmh) if err != nil { - r.Log.WithError(err).Errorf("Error updating hardwaredetails") + log.WithError(err).Errorf("Error updating hardwaredetails") return reconcileError{err}.Result() } } - result = r.reconcileAgentSpec(bmh, agent) + result = r.reconcileAgentSpec(log, bmh, agent) if result.Dirty() { err := r.Client.Update(ctx, agent) if err != nil { - r.Log.WithError(err).Errorf("Error updating agent") + log.WithError(err).Errorf("Error updating agent") return reconcileError{err}.Result() } } @@ -169,17 +182,17 @@ func (r *BMACReconciler) Reconcile(ctx context.Context, req ctrl.Request) (ctrl. if result.Dirty() { err := r.Client.Update(ctx, bmh) if err != nil { - r.Log.WithError(err).Errorf("Error updating BMH detached annotation") + log.WithError(err).Errorf("Error updating BMH detached annotation") return reconcileError{err}.Result() } } - result = r.reconcileSpokeBMH(ctx, bmh, agent) + result = r.reconcileSpokeBMH(ctx, log, bmh, agent) if result.Dirty() { err := r.Client.Update(ctx, bmh) if err != nil { - r.Log.WithError(err).Errorf("Error adding BMH detached annotation after creating spoke BMH") + log.WithError(err).Errorf("Error adding BMH detached annotation after creating spoke BMH") return reconcileError{err}.Result() } } @@ -202,9 +215,9 @@ func (r *BMACReconciler) Reconcile(ctx context.Context, req ctrl.Request) (ctrl. // Unless there are errors, the agent should be `Approved` at the end of this // reconcile and a label should be set on it referencing the BMH. No changes to // the BMH should happen in this reconcile step. -func (r *BMACReconciler) reconcileAgentSpec(bmh *bmh_v1alpha1.BareMetalHost, agent *aiv1beta1.Agent) reconcileResult { +func (r *BMACReconciler) reconcileAgentSpec(log logrus.FieldLogger, bmh *bmh_v1alpha1.BareMetalHost, agent *aiv1beta1.Agent) reconcileResult { - r.Log.Debugf("Started Agent Spec reconcile for agent %s/%s and bmh %s/%s", agent.Namespace, agent.Name, bmh.Namespace, bmh.Name) + log.Debugf("Started Agent Spec reconcile for agent %s/%s and bmh %s/%s", agent.Namespace, agent.Name, bmh.Namespace, bmh.Name) // Do all the copying from the BMH annotations to the agent. @@ -392,38 +405,38 @@ func (r *BMACReconciler) reconcileAgentInventory(bmh *bmh_v1alpha1.BareMetalHost // The above changes will be done only if the ISODownloadURL value has already // been set in the `InfraEnv` resource and the Image.URL value has not been // set in the `BareMetalHost` -func (r *BMACReconciler) reconcileBMH(ctx context.Context, bmh *bmh_v1alpha1.BareMetalHost) reconcileResult { +func (r *BMACReconciler) reconcileBMH(ctx context.Context, log logrus.FieldLogger, bmh *bmh_v1alpha1.BareMetalHost) reconcileResult { // No need to reconcile if the image URL has been set in // the BMH already. if bmh.Spec.Image != nil && bmh.Spec.Image.URL != "" { return reconcileComplete{} } - r.Log.Debugf("Started BMH reconcile for %s/%s", bmh.Namespace, bmh.Name) - r.Log.Debugf("BMH value %v", bmh) + log.Debugf("Started BMH reconcile for %s/%s", bmh.Namespace, bmh.Name) + log.Debugf("BMH value %v", bmh) for ann, value := range bmh.Labels { - r.Log.Debugf("BMH label %s value %s", ann, value) + log.Debugf("BMH label %s value %s", ann, value) // Find the `BMH_INFRA_ENV_LABEL`, get the infraEnv configured in it // and copy the ISO Url from the InfraEnv to the BMH resource. if ann == BMH_INFRA_ENV_LABEL { infraEnv := &aiv1beta1.InfraEnv{} - r.Log.Debugf("Loading InfraEnv %s", value) + log.Debugf("Loading InfraEnv %s", value) if err := r.Get(ctx, types.NamespacedName{Name: value, Namespace: bmh.Namespace}, infraEnv); err != nil { - r.Log.WithError(err).Errorf("failed to get infraEnv resource %s/%s", bmh.Namespace, value) + log.WithError(err).Errorf("failed to get infraEnv resource %s/%s", bmh.Namespace, value) return reconcileError{client.IgnoreNotFound(err)} } if infraEnv.Status.ISODownloadURL == "" { // the image has not been created yet, try later. - r.Log.Infof("Image URL for InfraEnv (%s/%s) not available yet. Waiting for new reconcile for BareMetalHost %s/%s", + log.Infof("Image URL for InfraEnv (%s/%s) not available yet. Waiting for new reconcile for BareMetalHost %s/%s", infraEnv.Namespace, infraEnv.Name, bmh.Namespace, bmh.Name) return reconcileComplete{} } - r.Log.Debugf("Setting attributes in BMH") + log.Debugf("Setting attributes in BMH") // We'll just overwrite this at this point // since the nullness and emptyness checks // are done at the beginning of this function. @@ -455,7 +468,7 @@ func (r *BMACReconciler) reconcileBMH(ctx context.Context, bmh *bmh_v1alpha1.Bar // now needs to be removed so that Ironic can manage the host. delete(bmh.ObjectMeta.Annotations, BMH_DETACHED_ANNOTATION) - r.Log.Infof("Image URL has been set in the BareMetalHost %s/%s", bmh.Namespace, bmh.Name) + log.Infof("Image URL has been set in the BareMetalHost %s/%s", bmh.Namespace, bmh.Name) return reconcileComplete{true} } } @@ -472,10 +485,10 @@ func (r *BMACReconciler) reconcileBMH(ctx context.Context, bmh *bmh_v1alpha1.Bar // - Creates a new Machine // - Create BMH with externallyProvisioned set to true and set the newly created machine as ConsumerRef // BMH_HARDWARE_DETAILS_ANNOTATION is needed for auto approval of the CSR. -func (r *BMACReconciler) reconcileSpokeBMH(ctx context.Context, bmh *bmh_v1alpha1.BareMetalHost, agent *aiv1beta1.Agent) reconcileResult { +func (r *BMACReconciler) reconcileSpokeBMH(ctx context.Context, log logrus.FieldLogger, bmh *bmh_v1alpha1.BareMetalHost, agent *aiv1beta1.Agent) reconcileResult { // Only worker role is supported for day2 operation if agent.Spec.Role != models.HostRoleWorker || agent.Spec.ClusterDeploymentName == nil { - r.Log.Debugf("Skipping spoke BareMetalHost reconcile for agent %s/%s, role %s and clusterDeployment %s.", agent.Namespace, agent.Name, agent.Spec.Role, agent.Spec.ClusterDeploymentName) + log.Debugf("Skipping spoke BareMetalHost reconcile for agent %s/%s, role %s and clusterDeployment %s.", agent.Namespace, agent.Name, agent.Spec.Role, agent.Spec.ClusterDeploymentName) return reconcileComplete{} } @@ -485,13 +498,13 @@ func (r *BMACReconciler) reconcileSpokeBMH(ctx context.Context, bmh *bmh_v1alpha } clusterDeployment := &hivev1.ClusterDeployment{} if err := r.Get(ctx, cdKey, clusterDeployment); err != nil { - r.Log.WithError(err).Errorf("failed to get clusterDeployment resource %s/%s", cdKey.Namespace, cdKey.Name) + log.WithError(err).Errorf("failed to get clusterDeployment resource %s/%s", cdKey.Namespace, cdKey.Name) return reconcileError{err} } // If the cluster is not installed yet, we can't get kubeconfig for the cluster yet. if !clusterDeployment.Spec.Installed { - r.Log.Infof("ClusterDeployment %s/%s for agent %s/%s is not installed yet", clusterDeployment.Namespace, clusterDeployment.Name, agent.Namespace, agent.Name) + log.Infof("ClusterDeployment %s/%s for agent %s/%s is not installed yet", clusterDeployment.Namespace, clusterDeployment.Name, agent.Namespace, agent.Name) // If cluster is not Installed, wait until a reconcile is trigged by a ClusterDeployment watch event instead return reconcileComplete{} } @@ -501,7 +514,7 @@ func (r *BMACReconciler) reconcileSpokeBMH(ctx context.Context, bmh *bmh_v1alpha name := fmt.Sprintf(adminKubeConfigStringTemplate, clusterDeployment.Name) err := r.Get(ctx, types.NamespacedName{Namespace: clusterDeployment.Namespace, Name: name}, secret) if err != nil && errors.IsNotFound(err) { - r.Log.WithError(err).Errorf("failed to get secret resource %s/%s", clusterDeployment.Namespace, name) + log.WithError(err).Errorf("failed to get secret resource %s/%s", clusterDeployment.Namespace, name) // TODO: If secret is not found, wait until a reconcile is trigged by a watch event instead return reconcileComplete{} } else if err != nil { @@ -510,25 +523,25 @@ func (r *BMACReconciler) reconcileSpokeBMH(ctx context.Context, bmh *bmh_v1alpha spokeClient, err := r.getSpokeClient(secret) if err != nil { - r.Log.WithError(err).Errorf("failed to create spoke kubeclient") + log.WithError(err).Errorf("failed to create spoke kubeclient") return reconcileError{err} } - machine, err := r.ensureSpokeMachine(ctx, spokeClient, bmh, clusterDeployment) + machine, err := r.ensureSpokeMachine(ctx, log, spokeClient, bmh, clusterDeployment) if err != nil { - r.Log.WithError(err).Errorf("failed to create or update spoke Machine") + log.WithError(err).Errorf("failed to create or update spoke Machine") return reconcileError{err} } - _, err = r.ensureSpokeBMHSecret(ctx, spokeClient, bmh) + _, err = r.ensureSpokeBMHSecret(ctx, log, spokeClient, bmh) if err != nil { - r.Log.WithError(err).Errorf("failed to create or update spoke BareMetalHost Secret") + log.WithError(err).Errorf("failed to create or update spoke BareMetalHost Secret") return reconcileError{err} } - _, err = r.ensureSpokeBMH(ctx, spokeClient, bmh, machine, agent) + _, err = r.ensureSpokeBMH(ctx, log, spokeClient, bmh, machine, agent) if err != nil { - r.Log.WithError(err).Errorf("failed to create or update spoke BareMetalHost") + log.WithError(err).Errorf("failed to create or update spoke BareMetalHost") return reconcileError{err} } @@ -762,27 +775,27 @@ func (r *BMACReconciler) findBMHByInfraEnv(ctx context.Context, infraEnv *aiv1be return bmhs, nil } -func (r *BMACReconciler) ensureSpokeBMH(ctx context.Context, spokeClient client.Client, bmh *bmh_v1alpha1.BareMetalHost, machine *machinev1beta1.Machine, agent *aiv1beta1.Agent) (*bmh_v1alpha1.BareMetalHost, error) { +func (r *BMACReconciler) ensureSpokeBMH(ctx context.Context, log logrus.FieldLogger, spokeClient client.Client, bmh *bmh_v1alpha1.BareMetalHost, machine *machinev1beta1.Machine, agent *aiv1beta1.Agent) (*bmh_v1alpha1.BareMetalHost, error) { bmhSpoke, mutateFn := r.newSpokeBMH(bmh, machine, agent) if result, err := controllerutil.CreateOrUpdate(ctx, spokeClient, bmhSpoke, mutateFn); err != nil { return nil, err } else if result != controllerutil.OperationResultNone { - r.Log.Info("Spoke BareMetalHost created") + log.Info("Spoke BareMetalHost created") } return bmhSpoke, nil } -func (r *BMACReconciler) ensureSpokeMachine(ctx context.Context, spokeClient client.Client, bmh *bmh_v1alpha1.BareMetalHost, clusterDeployment *hivev1.ClusterDeployment) (*machinev1beta1.Machine, error) { +func (r *BMACReconciler) ensureSpokeMachine(ctx context.Context, log logrus.FieldLogger, spokeClient client.Client, bmh *bmh_v1alpha1.BareMetalHost, clusterDeployment *hivev1.ClusterDeployment) (*machinev1beta1.Machine, error) { machineSpoke, mutateFn := r.newSpokeMachine(bmh, clusterDeployment) if result, err := controllerutil.CreateOrUpdate(ctx, spokeClient, machineSpoke, mutateFn); err != nil { return nil, err } else if result != controllerutil.OperationResultNone { - r.Log.Info("Spoke Machine created") + log.Info("Spoke Machine created") } return machineSpoke, nil } -func (r *BMACReconciler) ensureSpokeBMHSecret(ctx context.Context, spokeClient client.Client, bmh *bmh_v1alpha1.BareMetalHost) (*corev1.Secret, error) { +func (r *BMACReconciler) ensureSpokeBMHSecret(ctx context.Context, log logrus.FieldLogger, spokeClient client.Client, bmh *bmh_v1alpha1.BareMetalHost) (*corev1.Secret, error) { secretName := bmh.Spec.BMC.CredentialsName secret := &corev1.Secret{} err := r.Get(ctx, types.NamespacedName{Namespace: bmh.Namespace, Name: secretName}, secret) @@ -793,7 +806,7 @@ func (r *BMACReconciler) ensureSpokeBMHSecret(ctx context.Context, spokeClient c if result, err := controllerutil.CreateOrUpdate(ctx, spokeClient, secretSpoke, mutateFn); err != nil { return nil, err } else if result != controllerutil.OperationResultNone { - r.Log.Info("Spoke BareMetalHost Secret created") + log.Info("Spoke BareMetalHost Secret created") } return secretSpoke, nil } diff --git a/internal/controller/controllers/clusterdeployments_controller.go b/internal/controller/controllers/clusterdeployments_controller.go index 7032a36f02e..f0d5b0d1890 100644 --- a/internal/controller/controllers/clusterdeployments_controller.go +++ b/internal/controller/controllers/clusterdeployments_controller.go @@ -39,6 +39,7 @@ import ( "github.com/openshift/assisted-service/internal/manifests" "github.com/openshift/assisted-service/models" "github.com/openshift/assisted-service/pkg/auth" + logutil "github.com/openshift/assisted-service/pkg/log" "github.com/openshift/assisted-service/restapi/operations/installer" operations "github.com/openshift/assisted-service/restapi/operations/manifests" hivev1 "github.com/openshift/hive/apis/hive/v1" @@ -95,14 +96,25 @@ type ClusterDeploymentsReconciler struct { // +kubebuilder:rbac:groups=extensions.hive.openshift.io,resources=agentclusterinstalls/status,verbs=get;update;patch // +kubebuilder:rbac:groups=extensions.hive.openshift.io,resources=agentclusterinstalls/finalizers,verbs=update -func (r *ClusterDeploymentsReconciler) Reconcile(ctx context.Context, req ctrl.Request) (ctrl.Result, error) { - r.Log.Infof("Reconcile has been called for ClusterDeployment name=%s namespace=%s", req.Name, req.Namespace) +func (r *ClusterDeploymentsReconciler) Reconcile(origCtx context.Context, req ctrl.Request) (ctrl.Result, error) { + ctx := addRequestIdIfNeeded(origCtx) + logFields := logrus.Fields{ + "cluster_deployment": req.Name, + "cluster_deployment_namespace": req.Namespace, + } + log := logutil.FromContext(ctx, r.Log).WithFields(logFields) + + defer func() { + log.Info("ClusterDeployment Reconcile ended") + }() + + log.Info("ClusterDeployment Reconcile started") clusterDeployment := &hivev1.ClusterDeployment{} clusterInstallDeleted := false if err := r.Get(ctx, req.NamespacedName, clusterDeployment); err != nil { - r.Log.WithError(err).Errorf("failed to get ClusterDeployment name=%s namespace=%s", req.Name, req.Namespace) + log.WithError(err).Errorf("failed to get ClusterDeployment name=%s namespace=%s", req.Name, req.Namespace) return ctrl.Result{}, client.IgnoreNotFound(err) } @@ -113,7 +125,7 @@ func (r *ClusterDeploymentsReconciler) Reconcile(ctx context.Context, req ctrl.R clusterInstall := &hiveext.AgentClusterInstall{} if clusterDeployment.Spec.ClusterInstallRef == nil { - r.Log.Infof("AgentClusterInstall not set for ClusterDeployment %s", clusterDeployment.Name) + log.Infof("AgentClusterInstall not set for ClusterDeployment %s", clusterDeployment.Name) return ctrl.Result{}, nil } @@ -128,30 +140,33 @@ func (r *ClusterDeploymentsReconciler) Reconcile(ctx context.Context, req ctrl.R if k8serrors.IsNotFound(err) { // mark that clusterInstall was already deleted so we skip it if needed. clusterInstallDeleted = true - r.Log.WithField("AgentClusterInstall", aciName).Infof("AgentClusterInstall does not exist for ClusterDeployment %s", clusterDeployment.Name) + log.WithField("AgentClusterInstall", aciName).Infof("AgentClusterInstall does not exist for ClusterDeployment %s", clusterDeployment.Name) if clusterDeployment.ObjectMeta.DeletionTimestamp.IsZero() { // we have no agentClusterInstall and clusterDeployment is not being deleted. stop reconciliation. return ctrl.Result{}, nil } } else { - r.Log.WithError(err).Errorf("failed to get AgentClusterInstall name=%s namespace=%s", aciName, clusterDeployment.Namespace) + log.WithError(err).Errorf("failed to get AgentClusterInstall name=%s namespace=%s", aciName, clusterDeployment.Namespace) return ctrl.Result{Requeue: true}, err } } if !clusterInstallDeleted { - aciReply, aciErr := r.agentClusterInstallFinalizer(ctx, req, clusterInstall) + logFields["agent_cluster_install"] = clusterInstall.Name + logFields["agent_cluster_install_namespace"] = clusterInstall.Namespace + log = logutil.FromContext(ctx, log).WithFields(logFields) + aciReply, aciErr := r.agentClusterInstallFinalizer(ctx, log, req, clusterInstall) if aciReply != nil { return *aciReply, aciErr } } - cdReplay, cdErr := r.clusterDeploymentFinalizer(ctx, clusterDeployment) + cdReplay, cdErr := r.clusterDeploymentFinalizer(ctx, log, clusterDeployment) if cdReplay != nil { return *cdReplay, cdErr } - err = r.ensureOwnerRef(ctx, clusterDeployment, clusterInstall) + err = r.ensureOwnerRef(ctx, log, clusterDeployment, clusterInstall) if err != nil { return ctrl.Result{Requeue: true}, err } @@ -159,75 +174,75 @@ func (r *ClusterDeploymentsReconciler) Reconcile(ctx context.Context, req ctrl.R cluster, err := r.Installer.GetClusterByKubeKey(req.NamespacedName) if errors.Is(err, gorm.ErrRecordNotFound) { if !isInstalled(clusterDeployment, clusterInstall) { - return r.createNewCluster(ctx, req.NamespacedName, clusterDeployment, clusterInstall) + return r.createNewCluster(ctx, log, req.NamespacedName, clusterDeployment, clusterInstall) } if !r.isSNO(clusterInstall) { - return r.createNewDay2Cluster(ctx, req.NamespacedName, clusterDeployment, clusterInstall) + return r.createNewDay2Cluster(ctx, log, req.NamespacedName, clusterDeployment, clusterInstall) } // cluster is installed and SNO. Clear EventsURL clusterInstall.Status.DebugInfo.EventsURL = "" if updateErr := r.Status().Update(ctx, clusterInstall); updateErr != nil { - r.Log.WithError(updateErr).Error("failed to update ClusterDeployment Status") + log.WithError(updateErr).Error("failed to update ClusterDeployment Status") return ctrl.Result{Requeue: true}, nil } return ctrl.Result{Requeue: false}, nil } if err != nil { - return r.updateStatus(ctx, clusterInstall, cluster, err) + return r.updateStatus(ctx, log, clusterInstall, cluster, err) } // check for updates from user, compare spec and update if needed - err = r.updateIfNeeded(ctx, clusterDeployment, clusterInstall, cluster) + err = r.updateIfNeeded(ctx, log, clusterDeployment, clusterInstall, cluster) if err != nil { - return r.updateStatus(ctx, clusterInstall, cluster, err) + return r.updateStatus(ctx, log, clusterInstall, cluster, err) } // check for install config overrides and update if needed - err = r.updateInstallConfigOverrides(ctx, clusterInstall, cluster) + err = r.updateInstallConfigOverrides(ctx, log, clusterInstall, cluster) if err != nil { - return r.updateStatus(ctx, clusterInstall, cluster, err) + return r.updateStatus(ctx, log, clusterInstall, cluster, err) } // In case the Cluster is a Day 1 cluster and is installed, update the Metadata and create secrets for credentials if *cluster.Status == models.ClusterStatusInstalled && swag.StringValue(cluster.Kind) == models.ClusterKindCluster { if !isInstalled(clusterDeployment, clusterInstall) { // create secrets and update status - err = r.updateClusterMetadata(ctx, clusterDeployment, cluster, clusterInstall) - return r.updateStatus(ctx, clusterInstall, cluster, err) + err = r.updateClusterMetadata(ctx, log, clusterDeployment, cluster, clusterInstall) + return r.updateStatus(ctx, log, clusterInstall, cluster, err) } else { // Delete Day1 Cluster - _, err = r.deregisterClusterIfNeeded(ctx, req.NamespacedName) + _, err = r.deregisterClusterIfNeeded(ctx, log, req.NamespacedName) if err != nil { - return r.updateStatus(ctx, clusterInstall, cluster, err) + return r.updateStatus(ctx, log, clusterInstall, cluster, err) } if !r.isSNO(clusterInstall) { //Create Day2 cluster - return r.createNewDay2Cluster(ctx, req.NamespacedName, clusterDeployment, clusterInstall) + return r.createNewDay2Cluster(ctx, log, req.NamespacedName, clusterDeployment, clusterInstall) } - return r.updateStatus(ctx, clusterInstall, cluster, err) + return r.updateStatus(ctx, log, clusterInstall, cluster, err) } } if swag.StringValue(cluster.Kind) == models.ClusterKindCluster { // Day 1 - return r.installDay1(ctx, clusterDeployment, clusterInstall, cluster) + return r.installDay1(ctx, log, clusterDeployment, clusterInstall, cluster) } else if swag.StringValue(cluster.Kind) == models.ClusterKindAddHostsCluster { // Day 2 - return r.installDay2Hosts(ctx, clusterDeployment, clusterInstall, cluster) + return r.installDay2Hosts(ctx, log, clusterDeployment, clusterInstall, cluster) } - return r.updateStatus(ctx, clusterInstall, cluster, nil) + return r.updateStatus(ctx, log, clusterInstall, cluster, nil) } -func (r *ClusterDeploymentsReconciler) agentClusterInstallFinalizer(ctx context.Context, req ctrl.Request, +func (r *ClusterDeploymentsReconciler) agentClusterInstallFinalizer(ctx context.Context, log logrus.FieldLogger, req ctrl.Request, clusterInstall *hiveext.AgentClusterInstall) (*ctrl.Result, error) { if clusterInstall.ObjectMeta.DeletionTimestamp.IsZero() { // clusterInstall not being deleted // Register a finalizer if it is absent. if !funk.ContainsString(clusterInstall.GetFinalizers(), AgentClusterInstallFinalizerName) { controllerutil.AddFinalizer(clusterInstall, AgentClusterInstallFinalizerName) if err := r.Update(ctx, clusterInstall); err != nil { - r.Log.WithError(err).Errorf("failed to add finalizer %s to resource %s %s", + log.WithError(err).Errorf("failed to add finalizer %s to resource %s %s", AgentClusterInstallFinalizerName, clusterInstall.Name, clusterInstall.Namespace) return &ctrl.Result{Requeue: true}, err } @@ -235,9 +250,9 @@ func (r *ClusterDeploymentsReconciler) agentClusterInstallFinalizer(ctx context. } else { // clusterInstall is being deleted if funk.ContainsString(clusterInstall.GetFinalizers(), AgentClusterInstallFinalizerName) { // deletion finalizer found, deregister the backend cluster and delete agents - reply, cleanUpErr := r.deregisterClusterIfNeeded(ctx, req.NamespacedName) + reply, cleanUpErr := r.deregisterClusterIfNeeded(ctx, log, req.NamespacedName) if cleanUpErr != nil { - r.Log.WithError(cleanUpErr).Errorf("failed to run pre-deletion cleanup for finalizer %s on resource %s %s", + log.WithError(cleanUpErr).Errorf("failed to run pre-deletion cleanup for finalizer %s on resource %s %s", AgentClusterInstallFinalizerName, clusterInstall.Name, clusterInstall.Namespace) return &reply, cleanUpErr } @@ -245,7 +260,7 @@ func (r *ClusterDeploymentsReconciler) agentClusterInstallFinalizer(ctx context. // remove our finalizer from the list and update it. controllerutil.RemoveFinalizer(clusterInstall, AgentClusterInstallFinalizerName) if err := r.Update(ctx, clusterInstall); err != nil { - r.Log.WithError(err).Errorf("failed to remove finalizer %s from resource %s %s", + log.WithError(err).Errorf("failed to remove finalizer %s from resource %s %s", AgentClusterInstallFinalizerName, clusterInstall.Name, clusterInstall.Namespace) return &ctrl.Result{Requeue: true}, err } @@ -256,22 +271,22 @@ func (r *ClusterDeploymentsReconciler) agentClusterInstallFinalizer(ctx context. return nil, nil } -func (r *ClusterDeploymentsReconciler) clusterDeploymentFinalizer(ctx context.Context, clusterDeployment *hivev1.ClusterDeployment) (*ctrl.Result, error) { +func (r *ClusterDeploymentsReconciler) clusterDeploymentFinalizer(ctx context.Context, log logrus.FieldLogger, clusterDeployment *hivev1.ClusterDeployment) (*ctrl.Result, error) { if clusterDeployment.ObjectMeta.DeletionTimestamp.IsZero() { // clusterDeployment not being deleted // Register a finalizer if it is absent. if !funk.ContainsString(clusterDeployment.GetFinalizers(), ClusterDeploymentFinalizerName) { controllerutil.AddFinalizer(clusterDeployment, ClusterDeploymentFinalizerName) if err := r.Update(ctx, clusterDeployment); err != nil { - r.Log.WithError(err).Errorf("failed to add finalizer %s to resource %s %s", + log.WithError(err).Errorf("failed to add finalizer %s to resource %s %s", ClusterDeploymentFinalizerName, clusterDeployment.Name, clusterDeployment.Namespace) return &ctrl.Result{Requeue: true}, err } } } else { // clusterDeployment is being deleted if funk.ContainsString(clusterDeployment.GetFinalizers(), ClusterDeploymentFinalizerName) { - reply, cleanUpErr := r.deleteClusterInstall(ctx, clusterDeployment) + reply, cleanUpErr := r.deleteClusterInstall(ctx, log, clusterDeployment) if cleanUpErr != nil { - r.Log.WithError(cleanUpErr).Errorf( + log.WithError(cleanUpErr).Errorf( "clusterDeployment %s %s is still waiting for clusterInstall %s to be deleted", clusterDeployment.Name, clusterDeployment.Namespace, clusterDeployment.Spec.ClusterInstallRef.Name, ) @@ -281,7 +296,7 @@ func (r *ClusterDeploymentsReconciler) clusterDeploymentFinalizer(ctx context.Co // remove our finalizer from the list and update it. controllerutil.RemoveFinalizer(clusterDeployment, ClusterDeploymentFinalizerName) if err := r.Update(ctx, clusterDeployment); err != nil { - r.Log.WithError(err).Errorf("failed to remove finalizer %s from resource %s %s", + log.WithError(err).Errorf("failed to remove finalizer %s from resource %s %s", ClusterDeploymentFinalizerName, clusterDeployment.Name, clusterDeployment.Namespace) return &ctrl.Result{Requeue: true}, err } @@ -300,61 +315,62 @@ func isInstalled(clusterDeployment *hivev1.ClusterDeployment, clusterInstall *hi return cond != nil && cond.Reason == InstalledReason } -func (r *ClusterDeploymentsReconciler) installDay1(ctx context.Context, clusterDeployment *hivev1.ClusterDeployment, clusterInstall *hiveext.AgentClusterInstall, cluster *common.Cluster) (ctrl.Result, error) { +func (r *ClusterDeploymentsReconciler) installDay1(ctx context.Context, log logrus.FieldLogger, clusterDeployment *hivev1.ClusterDeployment, + clusterInstall *hiveext.AgentClusterInstall, cluster *common.Cluster) (ctrl.Result, error) { ready, err := r.isReadyForInstallation(ctx, clusterDeployment, clusterInstall, cluster) if err != nil { - return r.updateStatus(ctx, clusterInstall, cluster, err) + return r.updateStatus(ctx, log, clusterInstall, cluster, err) } if ready { // create custom manifests if needed before installation - err = r.addCustomManifests(ctx, clusterInstall, cluster) + err = r.addCustomManifests(ctx, log, clusterInstall, cluster) if err != nil { - _, _ = r.updateStatus(ctx, clusterInstall, cluster, err) + _, _ = r.updateStatus(ctx, log, clusterInstall, cluster, err) // We decided to requeue with one minute timeout in order to give user a chance to fix manifest // this timeout allows us not to run reconcile too much time and // still have a nice feedback when user will fix the error return ctrl.Result{Requeue: true, RequeueAfter: 1 * time.Minute}, nil } - r.Log.Infof("Installing clusterDeployment %s %s", clusterDeployment.Name, clusterDeployment.Namespace) + log.Infof("Installing clusterDeployment %s %s", clusterDeployment.Name, clusterDeployment.Namespace) var ic *common.Cluster ic, err = r.Installer.InstallClusterInternal(ctx, installer.InstallClusterParams{ ClusterID: *cluster.ID, }) if err != nil { - return r.updateStatus(ctx, clusterInstall, cluster, err) + return r.updateStatus(ctx, log, clusterInstall, cluster, err) } - return r.updateStatus(ctx, clusterInstall, ic, err) + return r.updateStatus(ctx, log, clusterInstall, ic, err) } - return r.updateStatus(ctx, clusterInstall, cluster, nil) + return r.updateStatus(ctx, log, clusterInstall, cluster, nil) } -func (r *ClusterDeploymentsReconciler) installDay2Hosts(ctx context.Context, clusterDeployment *hivev1.ClusterDeployment, clusterInstall *hiveext.AgentClusterInstall, cluster *common.Cluster) (ctrl.Result, error) { +func (r *ClusterDeploymentsReconciler) installDay2Hosts(ctx context.Context, log logrus.FieldLogger, clusterDeployment *hivev1.ClusterDeployment, clusterInstall *hiveext.AgentClusterInstall, cluster *common.Cluster) (ctrl.Result, error) { for _, h := range cluster.Hosts { commonh, err := r.Installer.GetCommonHostInternal(ctx, cluster.ID.String(), h.ID.String()) if err != nil { - return r.updateStatus(ctx, clusterInstall, cluster, err) + return r.updateStatus(ctx, log, clusterInstall, cluster, err) } if r.HostApi.IsInstallable(h) && commonh.Approved { - r.Log.Infof("Installing Day2 host %s in %s %s", *h.ID, clusterDeployment.Name, clusterDeployment.Namespace) + log.Infof("Installing Day2 host %s in %s %s", *h.ID, clusterDeployment.Name, clusterDeployment.Namespace) err = r.Installer.InstallSingleDay2HostInternal(ctx, *cluster.ID, *h.ID) if err != nil { - return r.updateStatus(ctx, clusterInstall, cluster, err) + return r.updateStatus(ctx, log, clusterInstall, cluster, err) } } } - return r.updateStatus(ctx, clusterInstall, cluster, nil) + return r.updateStatus(ctx, log, clusterInstall, cluster, nil) } -func (r *ClusterDeploymentsReconciler) updateClusterMetadata(ctx context.Context, cluster *hivev1.ClusterDeployment, c *common.Cluster, clusterInstall *hiveext.AgentClusterInstall) error { +func (r *ClusterDeploymentsReconciler) updateClusterMetadata(ctx context.Context, log logrus.FieldLogger, cluster *hivev1.ClusterDeployment, c *common.Cluster, clusterInstall *hiveext.AgentClusterInstall) error { - s, err := r.ensureAdminPasswordSecret(ctx, cluster, c) + s, err := r.ensureAdminPasswordSecret(ctx, log, cluster, c) if err != nil { return err } - k, err := r.ensureKubeConfigSecret(ctx, cluster, c) + k, err := r.ensureKubeConfigSecret(ctx, log, cluster, c) if err != nil { return err } @@ -371,7 +387,7 @@ func (r *ClusterDeploymentsReconciler) updateClusterMetadata(ctx context.Context return r.Update(ctx, clusterInstall) } -func (r *ClusterDeploymentsReconciler) ensureAdminPasswordSecret(ctx context.Context, cluster *hivev1.ClusterDeployment, c *common.Cluster) (*corev1.Secret, error) { +func (r *ClusterDeploymentsReconciler) ensureAdminPasswordSecret(ctx context.Context, log logrus.FieldLogger, cluster *hivev1.ClusterDeployment, c *common.Cluster) (*corev1.Secret, error) { s := &corev1.Secret{} name := fmt.Sprintf(adminPasswordSecretStringTemplate, cluster.Name) getErr := r.Get(ctx, types.NamespacedName{Namespace: cluster.Namespace, Name: name}, s) @@ -388,10 +404,10 @@ func (r *ClusterDeploymentsReconciler) ensureAdminPasswordSecret(ctx context.Con "username": []byte(cred.Username), "password": []byte(cred.Password), } - return r.createClusterCredentialSecret(ctx, cluster, c, name, data, "kubeadmincreds") + return r.createClusterCredentialSecret(ctx, log, cluster, c, name, data, "kubeadmincreds") } -func (r *ClusterDeploymentsReconciler) ensureKubeConfigSecret(ctx context.Context, cluster *hivev1.ClusterDeployment, c *common.Cluster) (*corev1.Secret, error) { +func (r *ClusterDeploymentsReconciler) ensureKubeConfigSecret(ctx context.Context, log logrus.FieldLogger, cluster *hivev1.ClusterDeployment, c *common.Cluster) (*corev1.Secret, error) { s := &corev1.Secret{} name := fmt.Sprintf(adminKubeConfigStringTemplate, cluster.Name) getErr := r.Get(ctx, types.NamespacedName{Namespace: cluster.Namespace, Name: name}, s) @@ -412,10 +428,10 @@ func (r *ClusterDeploymentsReconciler) ensureKubeConfigSecret(ctx context.Contex "kubeconfig": respBytes, } - return r.createClusterCredentialSecret(ctx, cluster, c, name, data, "kubeconfig") + return r.createClusterCredentialSecret(ctx, log, cluster, c, name, data, "kubeconfig") } -func (r *ClusterDeploymentsReconciler) createClusterCredentialSecret(ctx context.Context, cluster *hivev1.ClusterDeployment, c *common.Cluster, name string, data map[string][]byte, secretType string) (*corev1.Secret, error) { +func (r *ClusterDeploymentsReconciler) createClusterCredentialSecret(ctx context.Context, log logrus.FieldLogger, cluster *hivev1.ClusterDeployment, c *common.Cluster, name string, data map[string][]byte, secretType string) (*corev1.Secret, error) { s := &corev1.Secret{ ObjectMeta: metav1.ObjectMeta{ Name: name, @@ -429,7 +445,7 @@ func (r *ClusterDeploymentsReconciler) createClusterCredentialSecret(ctx context deploymentGVK, err := apiutil.GVKForObject(cluster, r.Scheme) if err != nil { - r.Log.WithError(err).Errorf("error getting GVK for clusterdeployment") + log.WithError(err).Errorf("error getting GVK for clusterdeployment") return nil, err } @@ -528,6 +544,7 @@ func getHyperthreading(clusterInstall *hiveext.AgentClusterInstall) *string { } func (r *ClusterDeploymentsReconciler) updateIfNeeded(ctx context.Context, + log logrus.FieldLogger, clusterDeployment *hivev1.ClusterDeployment, clusterInstall *hiveext.AgentClusterInstall, cluster *common.Cluster) error { @@ -602,20 +619,20 @@ func (r *ClusterDeploymentsReconciler) updateIfNeeded(ctx context.Context, return err } - infraEnv, err = getInfraEnvByClusterDeployment(ctx, r.Log, r.Client, clusterDeployment.Name, clusterDeployment.Namespace) + infraEnv, err = getInfraEnvByClusterDeployment(ctx, log, r.Client, clusterDeployment.Name, clusterDeployment.Namespace) if err != nil { return errors.Wrap(err, fmt.Sprintf("failed to search for infraEnv for clusterDeployment %s", clusterDeployment.Name)) } - r.Log.Infof("Updated clusterDeployment %s/%s", clusterDeployment.Namespace, clusterDeployment.Name) + log.Infof("Updated clusterDeployment %s/%s", clusterDeployment.Namespace, clusterDeployment.Name) if notifyInfraEnv && infraEnv != nil { - r.Log.Infof("Notify that infraEnv %s should re-generate the image for clusterDeployment %s", infraEnv.Name, clusterDeployment.ClusterName) + log.Infof("Notify that infraEnv %s should re-generate the image for clusterDeployment %s", infraEnv.Name, clusterDeployment.ClusterName) r.CRDEventsHandler.NotifyInfraEnvUpdates(infraEnv.Name, infraEnv.Namespace) } return nil } -func (r *ClusterDeploymentsReconciler) updateInstallConfigOverrides(ctx context.Context, clusterInstall *hiveext.AgentClusterInstall, +func (r *ClusterDeploymentsReconciler) updateInstallConfigOverrides(ctx context.Context, log logrus.FieldLogger, clusterInstall *hiveext.AgentClusterInstall, cluster *common.Cluster) error { // handle InstallConfigOverrides update := false @@ -633,18 +650,18 @@ func (r *ClusterDeploymentsReconciler) updateInstallConfigOverrides(ctx context. if err != nil { return err } - r.Log.Infof("Updated InstallConfig overrides on clusterInstall %s/%s", clusterInstall.Namespace, clusterInstall.Name) + log.Infof("Updated InstallConfig overrides on clusterInstall %s/%s", clusterInstall.Namespace, clusterInstall.Name) return nil } return nil } -func (r *ClusterDeploymentsReconciler) syncManifests(ctx context.Context, cluster *common.Cluster, +func (r *ClusterDeploymentsReconciler) syncManifests(ctx context.Context, log logrus.FieldLogger, cluster *common.Cluster, clusterInstall *hiveext.AgentClusterInstall, alreadyCreatedManifests models.ListManifests) error { - r.Log.Debugf("Going to sync list of given with already created manifests") + log.Debugf("Going to sync list of given with already created manifests") - manifestsFromConfigMap, err := r.getClusterDeploymentManifest(ctx, clusterInstall) + manifestsFromConfigMap, err := r.getClusterDeploymentManifest(ctx, log, clusterInstall) if err != nil { return err } @@ -653,7 +670,7 @@ func (r *ClusterDeploymentsReconciler) syncManifests(ctx context.Context, cluste // skip errors for _, manifest := range alreadyCreatedManifests { if _, ok := manifestsFromConfigMap[manifest.FileName]; !ok { - r.Log.Infof("Deleting cluster deployment %s manifest %s", cluster.KubeKeyName, manifest.FileName) + log.Infof("Deleting cluster deployment %s manifest %s", cluster.KubeKeyName, manifest.FileName) _ = r.Manifests.DeleteClusterManifestInternal(ctx, operations.DeleteClusterManifestParams{ ClusterID: *cluster.ID, FileName: manifest.FileName, @@ -664,7 +681,7 @@ func (r *ClusterDeploymentsReconciler) syncManifests(ctx context.Context, cluste // create/update all manifests provided by configmap data for filename, manifest := range manifestsFromConfigMap { - r.Log.Infof("Creating cluster deployment %s manifest %s", cluster.KubeKeyName, filename) + log.Infof("Creating cluster deployment %s manifest %s", cluster.KubeKeyName, filename) _, err := r.Manifests.CreateClusterManifestInternal(ctx, operations.CreateClusterManifestParams{ ClusterID: *cluster.ID, CreateManifestParams: &models.CreateManifestParams{ @@ -673,14 +690,14 @@ func (r *ClusterDeploymentsReconciler) syncManifests(ctx context.Context, cluste Folder: swag.String(models.ManifestFolderOpenshift), }}) if err != nil { - r.Log.WithError(err).Errorf("Failed to create cluster deployment %s manifest %s", cluster.KubeKeyName, filename) + log.WithError(err).Errorf("Failed to create cluster deployment %s manifest %s", cluster.KubeKeyName, filename) return err } } return nil } -func (r *ClusterDeploymentsReconciler) getClusterDeploymentManifest(ctx context.Context, clusterInstall *hiveext.AgentClusterInstall) (map[string]string, error) { +func (r *ClusterDeploymentsReconciler) getClusterDeploymentManifest(ctx context.Context, log logrus.FieldLogger, clusterInstall *hiveext.AgentClusterInstall) (map[string]string, error) { configuredManifests := &corev1.ConfigMap{} configuredManifests.Data = map[string]string{} // get manifests from configmap if we have reference for it @@ -688,7 +705,7 @@ func (r *ClusterDeploymentsReconciler) getClusterDeploymentManifest(ctx context. err := r.Get(ctx, types.NamespacedName{Namespace: clusterInstall.Namespace, Name: clusterInstall.Spec.ManifestsConfigMapRef.Name}, configuredManifests) if err != nil { - r.Log.WithError(err).Errorf("Failed to get configmap %s in %s", + log.WithError(err).Errorf("Failed to get configmap %s in %s", clusterInstall.Spec.ManifestsConfigMapRef.Name, clusterInstall.Namespace) return nil, err } @@ -696,14 +713,14 @@ func (r *ClusterDeploymentsReconciler) getClusterDeploymentManifest(ctx context. return configuredManifests.Data, nil } -func (r *ClusterDeploymentsReconciler) addCustomManifests(ctx context.Context, clusterInstall *hiveext.AgentClusterInstall, - cluster *common.Cluster) error { +func (r *ClusterDeploymentsReconciler) addCustomManifests(ctx context.Context, log logrus.FieldLogger, + clusterInstall *hiveext.AgentClusterInstall, cluster *common.Cluster) error { alreadyCreatedManifests, err := r.Manifests.ListClusterManifestsInternal(ctx, operations.ListClusterManifestsParams{ ClusterID: *cluster.ID, }) if err != nil { - r.Log.WithError(err).Errorf("Failed to list manifests for %q cluster install", clusterInstall.Name) + log.WithError(err).Errorf("Failed to list manifests for %q cluster install", clusterInstall.Name) return err } @@ -711,11 +728,11 @@ func (r *ClusterDeploymentsReconciler) addCustomManifests(ctx context.Context, c // but we already added some in previous reconcile loop, we want to clean them. // if no reference were provided we will delete all manifests that were in the list if clusterInstall.Spec.ManifestsConfigMapRef == nil && len(alreadyCreatedManifests) == 0 { - r.Log.Debugf("Nothing to do, skipping manifest creation") + log.Debugf("Nothing to do, skipping manifest creation") return nil } - return r.syncManifests(ctx, cluster, clusterInstall, alreadyCreatedManifests) + return r.syncManifests(ctx, log, cluster, clusterInstall, alreadyCreatedManifests) } func (r *ClusterDeploymentsReconciler) isSNO(clusterInstall *hiveext.AgentClusterInstall) bool { @@ -725,23 +742,24 @@ func (r *ClusterDeploymentsReconciler) isSNO(clusterInstall *hiveext.AgentCluste func (r *ClusterDeploymentsReconciler) createNewCluster( ctx context.Context, + log logrus.FieldLogger, key types.NamespacedName, clusterDeployment *hivev1.ClusterDeployment, clusterInstall *hiveext.AgentClusterInstall) (ctrl.Result, error) { - r.Log.Infof("Creating a new clusterDeployment %s %s", clusterDeployment.Name, clusterDeployment.Namespace) + log.Infof("Creating a new clusterDeployment %s %s", clusterDeployment.Name, clusterDeployment.Namespace) spec := clusterDeployment.Spec pullSecret, err := getPullSecret(ctx, r.Client, spec.PullSecretRef, key.Namespace) if err != nil { - r.Log.WithError(err).Error("failed to get pull secret") - return r.updateStatus(ctx, clusterInstall, nil, err) + log.WithError(err).Error("failed to get pull secret") + return r.updateStatus(ctx, log, clusterInstall, nil, err) } openshiftVersion, err := r.addOpenshiftVersion(ctx, clusterInstall.Spec, pullSecret) if err != nil { - r.Log.WithError(err).Error("failed to add OCP version") - return r.updateStatus(ctx, clusterInstall, nil, err) + log.WithError(err).Error("failed to add OCP version") + return r.updateStatus(ctx, log, clusterInstall, nil, err) } clusterParams := &models.ClusterCreateParams{ @@ -778,30 +796,31 @@ func (r *ClusterDeploymentsReconciler) createNewCluster( NewClusterParams: clusterParams, }) - return r.updateStatus(ctx, clusterInstall, c, err) + return r.updateStatus(ctx, log, clusterInstall, c, err) } func (r *ClusterDeploymentsReconciler) createNewDay2Cluster( ctx context.Context, + log logrus.FieldLogger, key types.NamespacedName, clusterDeployment *hivev1.ClusterDeployment, clusterInstall *hiveext.AgentClusterInstall) (ctrl.Result, error) { - r.Log.Infof("Creating a new Day2 Cluster %s %s", clusterDeployment.Name, clusterDeployment.Namespace) + log.Infof("Creating a new Day2 Cluster %s %s", clusterDeployment.Name, clusterDeployment.Namespace) spec := clusterDeployment.Spec id := strfmt.UUID(uuid.New().String()) apiVipDnsname := fmt.Sprintf("api.%s.%s", spec.ClusterName, spec.BaseDomain) pullSecret, err := getPullSecret(ctx, r.Client, spec.PullSecretRef, key.Namespace) if err != nil { - r.Log.WithError(err).Error("failed to get pull secret") - return r.updateStatus(ctx, clusterInstall, nil, err) + log.WithError(err).Error("failed to get pull secret") + return r.updateStatus(ctx, log, clusterInstall, nil, err) } openshiftVersion, err := r.addOpenshiftVersion(ctx, clusterInstall.Spec, pullSecret) if err != nil { - r.Log.WithError(err).Error("failed to add OCP version") - return r.updateStatus(ctx, clusterInstall, nil, err) + log.WithError(err).Error("failed to add OCP version") + return r.updateStatus(ctx, log, clusterInstall, nil, err) } clusterParams := &models.AddHostsClusterCreateParams{ @@ -815,7 +834,7 @@ func (r *ClusterDeploymentsReconciler) createNewDay2Cluster( NewAddHostsClusterParams: clusterParams, }) - return r.updateStatus(ctx, clusterInstall, c, err) + return r.updateStatus(ctx, log, clusterInstall, c, err) } func (r *ClusterDeploymentsReconciler) getReleaseImage(ctx context.Context, spec hiveext.AgentClusterInstallSpec) (string, error) { @@ -844,7 +863,7 @@ func (r *ClusterDeploymentsReconciler) addOpenshiftVersion( return openshiftVersion, nil } -func (r *ClusterDeploymentsReconciler) deregisterClusterIfNeeded(ctx context.Context, key types.NamespacedName) (ctrl.Result, error) { +func (r *ClusterDeploymentsReconciler) deregisterClusterIfNeeded(ctx context.Context, log logrus.FieldLogger, key types.NamespacedName) (ctrl.Result, error) { buildReply := func(err error) (ctrl.Result, error) { reply := ctrl.Result{} @@ -853,7 +872,7 @@ func (r *ClusterDeploymentsReconciler) deregisterClusterIfNeeded(ctx context.Con } reply.RequeueAfter = defaultRequeueAfterOnError err = errors.Wrapf(err, "failed to deregister cluster: %s", key.Name) - r.Log.Error(err) + log.Error(err) return reply, err } @@ -874,16 +893,16 @@ func (r *ClusterDeploymentsReconciler) deregisterClusterIfNeeded(ctx context.Con return buildReply(err) } // Delete agents because their backend cluster got deregistered. - if err = r.DeleteClusterDeploymentAgents(ctx, key); err != nil { + if err = r.DeleteClusterDeploymentAgents(ctx, log, key); err != nil { return buildReply(err) } - r.Log.Infof("Cluster resource deleted, Unregistered cluster: %s", c.ID.String()) + log.Infof("Cluster resource deleted, Unregistered cluster: %s", c.ID.String()) return buildReply(nil) } -func (r *ClusterDeploymentsReconciler) deleteClusterInstall(ctx context.Context, clusterDeployment *hivev1.ClusterDeployment) (ctrl.Result, error) { +func (r *ClusterDeploymentsReconciler) deleteClusterInstall(ctx context.Context, log logrus.FieldLogger, clusterDeployment *hivev1.ClusterDeployment) (ctrl.Result, error) { buildReply := func(err error) (ctrl.Result, error) { reply := ctrl.Result{} @@ -892,7 +911,7 @@ func (r *ClusterDeploymentsReconciler) deleteClusterInstall(ctx context.Context, } reply.RequeueAfter = defaultRequeueAfterOnError err = errors.Wrapf(err, "clusterInstall: %s not deleted", clusterDeployment.Spec.ClusterInstallRef.Name) - r.Log.Error(err) + log.Error(err) return reply, err } @@ -919,18 +938,18 @@ func (r *ClusterDeploymentsReconciler) deleteClusterInstall(ctx context.Context, return buildReply(err) } -func (r *ClusterDeploymentsReconciler) DeleteClusterDeploymentAgents(ctx context.Context, clusterDeployment types.NamespacedName) error { +func (r *ClusterDeploymentsReconciler) DeleteClusterDeploymentAgents(ctx context.Context, log logrus.FieldLogger, clusterDeployment types.NamespacedName) error { agents := &aiv1beta1.AgentList{} - r.Log = r.Log.WithFields(logrus.Fields{"clusterDeployment": clusterDeployment.Name, "namespace": clusterDeployment.Namespace}) + log = log.WithFields(logrus.Fields{"clusterDeployment": clusterDeployment.Name, "namespace": clusterDeployment.Namespace}) if err := r.List(ctx, agents); err != nil { return err } for i, clusterAgent := range agents.Items { if clusterAgent.Spec.ClusterDeploymentName.Name == clusterDeployment.Name && clusterAgent.Spec.ClusterDeploymentName.Namespace == clusterDeployment.Namespace { - r.Log.Infof("delete agent %s namespace %s", clusterAgent.Name, clusterAgent.Namespace) + log.Infof("delete agent %s namespace %s", clusterAgent.Name, clusterAgent.Namespace) if err := r.Client.Delete(ctx, &agents.Items[i]); err != nil { - r.Log.WithError(err).Errorf("Failed to delete resource %s %s", clusterAgent.Name, clusterAgent.Namespace) + log.WithError(err).Errorf("Failed to delete resource %s %s", clusterAgent.Name, clusterAgent.Namespace) return err } } @@ -959,12 +978,17 @@ func (r *ClusterDeploymentsReconciler) SetupWithManager(mgr ctrl.Manager) error // Reconcile the ClusterDeployment referenced by this AgentClusterInstall. mapClusterInstallToClusterDeployment := func(a client.Object) []reconcile.Request { + log := logutil.FromContext(context.Background(), r.Log).WithFields( + logrus.Fields{ + "agent_cluster_install": a.GetName(), + "agent_cluster_install_namespace": a.GetNamespace(), + }) aci, ok := a.(*hiveext.AgentClusterInstall) if !ok { - r.Log.Errorf("%v was not an AgentClusterInstall", a) // shouldn't be possible + log.Errorf("%v was not an AgentClusterInstall", a) // shouldn't be possible return []reconcile.Request{} } - r.Log.Debugf("Map ACI : %s %s CD ref name %s", aci.Namespace, aci.Name, aci.Spec.ClusterDeploymentRef.Name) + log.Debugf("Map ACI : %s %s CD ref name %s", aci.Namespace, aci.Name, aci.Spec.ClusterDeploymentRef.Name) return []reconcile.Request{ { NamespacedName: types.NamespacedName{ @@ -987,12 +1011,12 @@ func (r *ClusterDeploymentsReconciler) SetupWithManager(mgr ctrl.Manager) error // updateStatus is updating all the AgentClusterInstall Conditions. // In case that an error has occured when trying to sync the Spec, the error (syncErr) is presented in SpecSyncedCondition. // Internal bool differentiate between backend server error (internal HTTP 5XX) and user input error (HTTP 4XXX) -func (r *ClusterDeploymentsReconciler) updateStatus(ctx context.Context, clusterInstall *hiveext.AgentClusterInstall, c *common.Cluster, syncErr error) (ctrl.Result, error) { +func (r *ClusterDeploymentsReconciler) updateStatus(ctx context.Context, log logrus.FieldLogger, clusterInstall *hiveext.AgentClusterInstall, c *common.Cluster, syncErr error) (ctrl.Result, error) { clusterSpecSynced(clusterInstall, syncErr) if c != nil { clusterInstall.Status.ConnectivityMajorityGroups = c.ConnectivityMajorityGroups if clusterInstall.Status.DebugInfo.EventsURL == "" { - eventUrl, err := r.eventsURL(string(*c.ID)) + eventUrl, err := r.eventsURL(log, string(*c.ID)) if err != nil { return ctrl.Result{Requeue: true}, nil } @@ -1011,7 +1035,7 @@ func (r *ClusterDeploymentsReconciler) updateStatus(ctx context.Context, cluster } if updateErr := r.Status().Update(ctx, clusterInstall); updateErr != nil { - r.Log.WithError(updateErr).Error("failed to update ClusterDeployment Status") + log.WithError(updateErr).Error("failed to update ClusterDeployment Status") return ctrl.Result{Requeue: true}, nil } if syncErr != nil && !IsUserError(syncErr) { @@ -1020,14 +1044,14 @@ func (r *ClusterDeploymentsReconciler) updateStatus(ctx context.Context, cluster return ctrl.Result{}, nil } -func (r *ClusterDeploymentsReconciler) eventsURL(clusterId string) (string, error) { +func (r *ClusterDeploymentsReconciler) eventsURL(log logrus.FieldLogger, clusterId string) (string, error) { eventsURL := fmt.Sprintf("%s%s/clusters/%s/events", r.ServiceBaseURL, restclient.DefaultBasePath, clusterId) if r.AuthType != auth.TypeLocal { return eventsURL, nil } eventsURL, err := gencrypto.SignURL(eventsURL, clusterId) if err != nil { - r.Log.WithError(err).Error("failed to get Events URL") + log.WithError(err).Error("failed to get Events URL") return "", err } return eventsURL, nil @@ -1302,10 +1326,10 @@ func FindStatusCondition(conditions []hivev1.ClusterInstallCondition, conditionT } // ensureOwnerRef sets the owner reference of ClusterDeployment on AgentClusterInstall -func (r *ClusterDeploymentsReconciler) ensureOwnerRef(ctx context.Context, cd *hivev1.ClusterDeployment, ci *hiveext.AgentClusterInstall) error { +func (r *ClusterDeploymentsReconciler) ensureOwnerRef(ctx context.Context, log logrus.FieldLogger, cd *hivev1.ClusterDeployment, ci *hiveext.AgentClusterInstall) error { if err := controllerutil.SetOwnerReference(cd, ci, r.Scheme); err != nil { - r.Log.WithError(err).Error("error setting owner reference Agent Cluster Install") + log.WithError(err).Error("error setting owner reference Agent Cluster Install") return err } return r.Update(ctx, ci) diff --git a/internal/controller/controllers/common.go b/internal/controller/controllers/common.go index 55301993d84..a680cf569c6 100644 --- a/internal/controller/controllers/common.go +++ b/internal/controller/controllers/common.go @@ -7,7 +7,7 @@ import ( "strings" aiv1beta1 "github.com/openshift/assisted-service/internal/controller/api/v1beta1" - logutil "github.com/openshift/assisted-service/pkg/log" + "github.com/openshift/assisted-service/pkg/requestid" hivev1 "github.com/openshift/hive/apis/hive/v1" "github.com/pkg/errors" "github.com/sirupsen/logrus" @@ -46,8 +46,7 @@ func getPullSecret(ctx context.Context, c client.Client, ref *corev1.LocalObject return string(data), nil } -func getInfraEnvByClusterDeployment(ctx context.Context, logger logrus.FieldLogger, c client.Client, name, namespace string) (*aiv1beta1.InfraEnv, error) { - log := logutil.FromContext(ctx, logger) +func getInfraEnvByClusterDeployment(ctx context.Context, log logrus.FieldLogger, c client.Client, name, namespace string) (*aiv1beta1.InfraEnv, error) { infraEnvs := &aiv1beta1.InfraEnvList{} if err := c.List(ctx, infraEnvs); err != nil { log.WithError(err).Errorf("failed to search for infraEnv for clusterDeployment %s", name) @@ -127,3 +126,11 @@ func getReleaseImage(ctx context.Context, c client.Client, imageSetName string) return clusterImageSet.Spec.ReleaseImage, nil } + +func addRequestIdIfNeeded(ctx context.Context) context.Context { + ctxWithReqID := ctx + if requestid.FromContext(ctx) == "" { + ctxWithReqID = requestid.ToContext(ctx, requestid.NewID()) + } + return ctxWithReqID +} diff --git a/internal/controller/controllers/infraenv_controller.go b/internal/controller/controllers/infraenv_controller.go index 2559a6db53f..24027e8625a 100644 --- a/internal/controller/controllers/infraenv_controller.go +++ b/internal/controller/controllers/infraenv_controller.go @@ -62,22 +62,32 @@ type InfraEnvReconciler struct { // +kubebuilder:rbac:groups=agent-install.openshift.io,resources=infraenvs,verbs=get;list;watch;create;update;patch;delete // +kubebuilder:rbac:groups=agent-install.openshift.io,resources=infraenvs/status,verbs=get;update;patch -func (r *InfraEnvReconciler) Reconcile(ctx context.Context, req ctrl.Request) (ctrl.Result, error) { - r.Log.Infof("Reconcile has been called for InfraEnv name=%s namespace=%s", req.Name, req.Namespace) +func (r *InfraEnvReconciler) Reconcile(origCtx context.Context, req ctrl.Request) (ctrl.Result, error) { + ctx := addRequestIdIfNeeded(origCtx) + log := logutil.FromContext(ctx, r.Log).WithFields( + logrus.Fields{ + "infra_env": req.Name, + "infra_env_namespace": req.Namespace, + }) + + defer func() { + log.Info("InfraEnv Reconcile ended") + }() + + log.Info("InfraEnv Reconcile started") infraEnv := &aiv1beta1.InfraEnv{} if err := r.Get(ctx, req.NamespacedName, infraEnv); err != nil { return ctrl.Result{}, client.IgnoreNotFound(err) } - return r.ensureISO(ctx, infraEnv) + return r.ensureISO(ctx, log, infraEnv) } -func (r *InfraEnvReconciler) updateClusterIfNeeded(ctx context.Context, infraEnv *aiv1beta1.InfraEnv, cluster *common.Cluster) error { +func (r *InfraEnvReconciler) updateClusterIfNeeded(ctx context.Context, log logrus.FieldLogger, infraEnv *aiv1beta1.InfraEnv, cluster *common.Cluster) error { var ( params = &models.ClusterUpdateParams{} update bool - log = logutil.FromContext(ctx, r.Log) ) if infraEnv.Spec.Proxy != nil { @@ -116,11 +126,10 @@ func (r *InfraEnvReconciler) updateClusterIfNeeded(ctx context.Context, infraEnv return nil } -func (r *InfraEnvReconciler) updateClusterDiscoveryIgnitionIfNeeded(ctx context.Context, infraEnv *aiv1beta1.InfraEnv, cluster *common.Cluster) error { +func (r *InfraEnvReconciler) updateClusterDiscoveryIgnitionIfNeeded(ctx context.Context, log logrus.FieldLogger, infraEnv *aiv1beta1.InfraEnv, cluster *common.Cluster) error { var ( discoveryIgnitionParams = &models.DiscoveryIgnitionParams{} updateClusterIgnition bool - log = logutil.FromContext(ctx, r.Log) ) if infraEnv.Spec.IgnitionConfigOverride != "" && cluster.IgnitionConfigOverrides != infraEnv.Spec.IgnitionConfigOverride { discoveryIgnitionParams.Config = *swag.String(infraEnv.Spec.IgnitionConfigOverride) @@ -142,10 +151,10 @@ func (r *InfraEnvReconciler) updateClusterDiscoveryIgnitionIfNeeded(ctx context. return nil } -func (r *InfraEnvReconciler) buildMacInterfaceMap(nmStateConfig aiv1beta1.NMStateConfig) models.MacInterfaceMap { +func (r *InfraEnvReconciler) buildMacInterfaceMap(log logrus.FieldLogger, nmStateConfig aiv1beta1.NMStateConfig) models.MacInterfaceMap { macInterfaceMap := make(models.MacInterfaceMap, 0, len(nmStateConfig.Spec.Interfaces)) for _, cfg := range nmStateConfig.Spec.Interfaces { - r.Log.Debugf("adding MAC interface map to host static network config - Name: %s, MacAddress: %s ,", + log.Debugf("adding MAC interface map to host static network config - Name: %s, MacAddress: %s ,", cfg.Name, cfg.MacAddress) macInterfaceMap = append(macInterfaceMap, &models.MacInterfaceMapItems0{ MacAddress: cfg.MacAddress, @@ -155,7 +164,7 @@ func (r *InfraEnvReconciler) buildMacInterfaceMap(nmStateConfig aiv1beta1.NMStat return macInterfaceMap } -func (r *InfraEnvReconciler) processNMStateConfig(ctx context.Context, infraEnv *aiv1beta1.InfraEnv) ([]*models.HostStaticNetworkConfig, error) { +func (r *InfraEnvReconciler) processNMStateConfig(ctx context.Context, log logrus.FieldLogger, infraEnv *aiv1beta1.InfraEnv) ([]*models.HostStaticNetworkConfig, error) { var staticNetworkConfig []*models.HostStaticNetworkConfig if infraEnv.Spec.NMStateConfigLabelSelector.MatchLabels == nil { @@ -168,9 +177,9 @@ func (r *InfraEnvReconciler) processNMStateConfig(ctx context.Context, infraEnv return staticNetworkConfig, err } for _, nmStateConfig := range nmStateConfigs.Items { - r.Log.Debugf("found nmStateConfig: %s for infraEnv: %s", nmStateConfig.Name, infraEnv.Name) + log.Debugf("found nmStateConfig: %s for infraEnv: %s", nmStateConfig.Name, infraEnv.Name) staticNetworkConfig = append(staticNetworkConfig, &models.HostStaticNetworkConfig{ - MacInterfaceMap: r.buildMacInterfaceMap(nmStateConfig), + MacInterfaceMap: r.buildMacInterfaceMap(log, nmStateConfig), NetworkYaml: string(nmStateConfig.Spec.NetConfig.Raw), }) } @@ -180,7 +189,7 @@ func (r *InfraEnvReconciler) processNMStateConfig(ctx context.Context, infraEnv // ensureISO generates ISO for the cluster if needed and will update the condition Reason and Message accordingly. // It returns a result that includes ISODownloadURL. -func (r *InfraEnvReconciler) ensureISO(ctx context.Context, infraEnv *aiv1beta1.InfraEnv) (ctrl.Result, error) { +func (r *InfraEnvReconciler) ensureISO(ctx context.Context, log logrus.FieldLogger, infraEnv *aiv1beta1.InfraEnv) (ctrl.Result, error) { var inventoryErr error var Requeue bool var updatedCluster *common.Cluster @@ -211,7 +220,7 @@ func (r *InfraEnvReconciler) ensureISO(ctx context.Context, infraEnv *aiv1beta1. Message: aiv1beta1.ImageStateFailedToCreate + ": " + clusterDeploymentRefErr.Error(), }) if updateErr := r.Status().Update(ctx, infraEnv); updateErr != nil { - r.Log.WithError(updateErr).Error("failed to update infraEnv status") + log.WithError(updateErr).Error("failed to update infraEnv status") } return ctrl.Result{Requeue: Requeue}, nil } @@ -237,19 +246,19 @@ func (r *InfraEnvReconciler) ensureISO(ctx context.Context, infraEnv *aiv1beta1. Message: aiv1beta1.ImageStateFailedToCreate + ": " + inventoryErr.Error(), }) if updateErr := r.Status().Update(ctx, infraEnv); updateErr != nil { - r.Log.WithError(updateErr).Error("failed to update infraEnv status") + log.WithError(updateErr).Error("failed to update infraEnv status") } return ctrl.Result{Requeue: Requeue}, nil } // Check for updates from user, compare spec and update the cluster - if err = r.updateClusterIfNeeded(ctx, infraEnv, cluster); err != nil { - return r.handleEnsureISOErrors(ctx, infraEnv, err) + if err = r.updateClusterIfNeeded(ctx, log, infraEnv, cluster); err != nil { + return r.handleEnsureISOErrors(ctx, log, infraEnv, err) } // Check for discovery ignition specific updates from user, compare spec and update the ignition config - if err = r.updateClusterDiscoveryIgnitionIfNeeded(ctx, infraEnv, cluster); err != nil { - return r.handleEnsureISOErrors(ctx, infraEnv, err) + if err = r.updateClusterDiscoveryIgnitionIfNeeded(ctx, log, infraEnv, cluster); err != nil { + return r.handleEnsureISOErrors(ctx, log, infraEnv, err) } isoParams := installer.GenerateClusterISOParams{ @@ -260,9 +269,9 @@ func (r *InfraEnvReconciler) ensureISO(ctx context.Context, infraEnv *aiv1beta1. }, } - staticNetworkConfig, err := r.processNMStateConfig(ctx, infraEnv) + staticNetworkConfig, err := r.processNMStateConfig(ctx, log, infraEnv) if err != nil { - return r.handleEnsureISOErrors(ctx, infraEnv, err) + return r.handleEnsureISOErrors(ctx, log, infraEnv, err) } if len(staticNetworkConfig) > 0 { isoParams.ImageCreateParams.StaticNetworkConfig = staticNetworkConfig @@ -271,21 +280,21 @@ func (r *InfraEnvReconciler) ensureISO(ctx context.Context, infraEnv *aiv1beta1. // Add openshift version to ensure it isn't missing in versions cache _, err = r.Installer.AddOpenshiftVersion(ctx, cluster.OcpReleaseImage, cluster.PullSecret) if err != nil { - return r.handleEnsureISOErrors(ctx, infraEnv, err) + return r.handleEnsureISOErrors(ctx, log, infraEnv, err) } // GenerateClusterISOInternal will generate an ISO only if there it was not generated before, // or something has changed in isoParams. updatedCluster, inventoryErr = r.Installer.GenerateClusterISOInternal(ctx, isoParams) if inventoryErr != nil { - return r.handleEnsureISOErrors(ctx, infraEnv, inventoryErr) + return r.handleEnsureISOErrors(ctx, log, infraEnv, inventoryErr) } // Image successfully generated. Reflect that in infraEnv obj and conditions - return r.updateEnsureISOSuccess(ctx, infraEnv, updatedCluster.ImageInfo) + return r.updateEnsureISOSuccess(ctx, log, infraEnv, updatedCluster.ImageInfo) } func (r *InfraEnvReconciler) updateEnsureISOSuccess( - ctx context.Context, infraEnv *aiv1beta1.InfraEnv, imageInfo *models.ImageInfo) (ctrl.Result, error) { + ctx context.Context, log logrus.FieldLogger, infraEnv *aiv1beta1.InfraEnv, imageInfo *models.ImageInfo) (ctrl.Result, error) { conditionsv1.SetStatusConditionNoHeartbeat(&infraEnv.Status.Conditions, conditionsv1.Condition{ Type: aiv1beta1.ImageCreatedCondition, Status: corev1.ConditionTrue, @@ -294,14 +303,14 @@ func (r *InfraEnvReconciler) updateEnsureISOSuccess( }) infraEnv.Status.ISODownloadURL = imageInfo.DownloadURL if updateErr := r.Status().Update(ctx, infraEnv); updateErr != nil { - r.Log.WithError(updateErr).Error("failed to update infraEnv status") + log.WithError(updateErr).Error("failed to update infraEnv status") return ctrl.Result{Requeue: true}, nil } return ctrl.Result{Requeue: false}, nil } func (r *InfraEnvReconciler) handleEnsureISOErrors( - ctx context.Context, infraEnv *aiv1beta1.InfraEnv, err error) (ctrl.Result, error) { + ctx context.Context, log logrus.FieldLogger, infraEnv *aiv1beta1.InfraEnv, err error) (ctrl.Result, error) { var ( currentReason = "" errMsg string @@ -315,7 +324,7 @@ func (r *InfraEnvReconciler) handleEnsureISOErrors( if imageBeingCreated(err) && currentReason != aiv1beta1.ImageCreationErrorReason { // Not an actual error, just an image generation in progress. err = nil Requeue = false - r.Log.Infof("Image %s being prepared for cluster %s", infraEnv.Name, infraEnv.ClusterName) + log.Infof("Image %s being prepared for cluster %s", infraEnv.Name, infraEnv.ClusterName) conditionsv1.SetStatusConditionNoHeartbeat(&infraEnv.Status.Conditions, conditionsv1.Condition{ Type: aiv1beta1.ImageCreatedCondition, Status: corev1.ConditionTrue, @@ -323,7 +332,7 @@ func (r *InfraEnvReconciler) handleEnsureISOErrors( Message: aiv1beta1.ImageStateCreated, }) } else { // Actual errors - r.Log.WithError(err).Error("infraEnv reconcile failed") + log.WithError(err).Error("infraEnv reconcile failed") if isClientError(err) { Requeue = false errMsg = ": " + err.Error() @@ -341,7 +350,7 @@ func (r *InfraEnvReconciler) handleEnsureISOErrors( infraEnv.Status.ISODownloadURL = "" } if updateErr := r.Status().Update(ctx, infraEnv); updateErr != nil { - r.Log.WithError(updateErr).Error("failed to update infraEnv status") + log.WithError(updateErr).Error("failed to update infraEnv status") } return ctrl.Result{Requeue: Requeue}, err } @@ -352,23 +361,28 @@ func imageBeingCreated(err error) bool { func (r *InfraEnvReconciler) SetupWithManager(mgr ctrl.Manager) error { mapNMStateConfigToInfraEnv := func(a client.Object) []reconcile.Request { + log := logutil.FromContext(context.Background(), r.Log).WithFields( + logrus.Fields{ + "nmstate_config": a.GetName(), + "nmstate_config_namespace": a.GetNamespace(), + }) infraEnvs := &aiv1beta1.InfraEnvList{} if len(a.GetLabels()) == 0 { - r.Log.Debugf("NMState config: %s has no labels", a.GetName()) + log.Debugf("NMState config: %s has no labels", a.GetName()) return []reconcile.Request{} } if err := r.List(context.Background(), infraEnvs, client.InNamespace(a.GetNamespace())); err != nil { - r.Log.Debugf("failed to list InfraEnvs") + log.Debugf("failed to list InfraEnvs") return []reconcile.Request{} } reply := make([]reconcile.Request, 0, len(infraEnvs.Items)) for labelName, labelValue := range a.GetLabels() { - r.Log.Debugf("Detected NMState config with label name: %s with value %s, about to search for a matching InfraEnv", + log.Debugf("Detected NMState config with label name: %s with value %s, about to search for a matching InfraEnv", labelName, labelValue) for _, infraEnv := range infraEnvs.Items { if infraEnv.Spec.NMStateConfigLabelSelector.MatchLabels[labelName] == labelValue { - r.Log.Debugf("Detected NMState config for InfraEnv: %s in namespace: %s", infraEnv.Name, infraEnv.Namespace) + log.Debugf("Detected NMState config for InfraEnv: %s in namespace: %s", infraEnv.Name, infraEnv.Namespace) reply = append(reply, reconcile.Request{NamespacedName: types.NamespacedName{ Namespace: infraEnv.Namespace, Name: infraEnv.Name, @@ -380,9 +394,14 @@ func (r *InfraEnvReconciler) SetupWithManager(mgr ctrl.Manager) error { } mapClusterDeploymentToInfraEnv := func(clusterDeployment client.Object) []reconcile.Request { + log := logutil.FromContext(context.Background(), r.Log).WithFields( + logrus.Fields{ + "cluster_deployment": clusterDeployment.GetName(), + "cluster_deployment_namespace": clusterDeployment.GetNamespace(), + }) infraEnvs := &aiv1beta1.InfraEnvList{} if err := r.List(context.Background(), infraEnvs, client.InNamespace(clusterDeployment.GetNamespace())); err != nil { - r.Log.Debugf("failed to list InfraEnvs") + log.Debugf("failed to list InfraEnvs") return []reconcile.Request{} }