Homogenize logs (#1168)

operators/cmd/manager/main.go

@@ -212,11 +212,14 @@ func execute() {
 		// restrict the operator to watch resources within a single namespace, unless empty
 		Namespace: viper.GetString(NamespaceFlagName),
 	}
+
+	// only expose prometheus metrics if provided a specific port
 	metricsPort := viper.GetInt(MetricsPortFlag)
 	if metricsPort != 0 {
+		log.Info("Exposing Prometheus metrics on /metrics", "port", metricsPort)
 		opts.MetricsBindAddress = fmt.Sprintf(":%d", metricsPort)
-		log.Info(fmt.Sprintf("Exposing Prometheus metrics on /metrics%s", opts.MetricsBindAddress))
 	}
+
 	mgr, err := manager.New(cfg, opts)
 	if err != nil {
 		log.Error(err, "unable to set up overall controller manager")

operators/pkg/controller/apmserver/apmserver_controller.go

@@ -154,14 +154,15 @@ func (r *ReconcileApmServer) Reconcile(request reconcile.Request) (reconcile.Res
 	// atomically update the iteration to support concurrent runs.
 	currentIteration := atomic.AddInt64(&r.iteration, 1)
 	iterationStartTime := time.Now()
-	log.Info("Start reconcile iteration", "iteration", currentIteration)
+	log.Info("Start reconcile iteration", "iteration", currentIteration, "namespace", request.Namespace, "as_name", request.Name)
 	defer func() {
-		log.Info("End reconcile iteration", "iteration", currentIteration, "took", time.Since(iterationStartTime))
+		log.Info("End reconcile iteration", "iteration", currentIteration, "took", time.Since(iterationStartTime), "namespace", request.Namespace, "as_name", request.Name)
 	}()
 
 	// Fetch the ApmServer resource
 	as := &apmv1alpha1.ApmServer{}
 	err := r.Get(request.NamespacedName, as)
+
 	if err != nil {
 		if errors.IsNotFound(err) {
 			// Object not found, return.  Created objects are automatically garbage collected.
@@ -173,7 +174,7 @@ func (r *ReconcileApmServer) Reconcile(request reconcile.Request) (reconcile.Res
 	}
 
 	if common.IsPaused(as.ObjectMeta) {
-		log.Info("Paused : skipping reconciliation", "iteration", currentIteration)
+		log.Info("Object is paused. Skipping reconciliation", "namespace", as.Namespace, "as_name", as.Name, "iteration", currentIteration)
 		return common.PauseRequeue, nil
 	}
 
@@ -218,7 +219,8 @@ func (r *ReconcileApmServer) reconcileApmServerDeployment(
 	as *apmv1alpha1.ApmServer,
 ) (State, error) {
 	if !as.Spec.Output.Elasticsearch.IsConfigured() {
-		log.Info("Aborting ApmServer deployment reconciliation as no Elasticsearch output is configured")
+		log.Info("Aborting ApmServer deployment reconciliation as no Elasticsearch output is configured",
+			"namespace", as.Namespace, "as_name", as.Name)
 		return state, nil
 	}
 
@@ -270,10 +272,10 @@ func (r *ReconcileApmServer) reconcileApmServerDeployment(
 				reconciledApmServerSecret.Data = expectedApmServerSecret.Data
 			},
 			PreCreate: func() {
-				log.Info("Creating apm server secret", "name", expectedApmServerSecret.Name)
+				log.Info("Creating apm server secret", "namespace", expectedApmServerSecret.Namespace, "secret_name", expectedApmServerSecret.Name, "as_name", as.Name)
 			},
 			PreUpdate: func() {
-				log.Info("Updating apm server secret", "name", expectedApmServerSecret.Name)
+				log.Info("Updating apm server secret", "namespace", expectedApmServerSecret.Namespace, "secret_name", expectedApmServerSecret.Name, "as_name", as.Name)
 			},
 		},
 	); err != nil {
@@ -387,8 +389,7 @@ func (r *ReconcileApmServer) updateStatus(state State) (reconcile.Result, error)
 	if state.ApmServer.Status.IsDegraded(current.Status) {
 		r.recorder.Event(current, corev1.EventTypeWarning, events.EventReasonUnhealthy, "Apm Server health degraded")
 	}
-	log.Info("Updating status", "iteration", atomic.LoadInt64(&r.iteration))
-
+	log.Info("Updating status", "namespace", state.ApmServer.Namespace, "as_name", state.ApmServer.Name, "iteration", atomic.LoadInt64(&r.iteration))
 	err := r.Status().Update(state.ApmServer)
 	if err != nil && errors.IsConflict(err) {
 		log.V(1).Info("Conflict while updating status")

operators/pkg/controller/apmserverelasticsearchassociation/apmserverelasticsearchassociation_controller.go

@@ -111,9 +111,9 @@ func (r *ReconcileApmServerElasticsearchAssociation) Reconcile(request reconcile
 	// atomically update the iteration to support concurrent runs.
 	currentIteration := atomic.AddInt64(&r.iteration, 1)
 	iterationStartTime := time.Now()
-	log.Info("Start reconcile iteration", "iteration", currentIteration)
+	log.Info("Start reconcile iteration", "iteration", currentIteration, "namespace", request.Namespace, "as_name", request.Name)
 	defer func() {
-		log.Info("End reconcile iteration", "iteration", currentIteration, "took", time.Since(iterationStartTime))
+		log.Info("End reconcile iteration", "iteration", currentIteration, "took", time.Since(iterationStartTime), "namespace", request.Namespace, "as_name", request.Name)
 	}()
 
 	var apmServer apmtype.ApmServer
@@ -127,7 +127,7 @@ func (r *ReconcileApmServerElasticsearchAssociation) Reconcile(request reconcile
 	}
 
 	if common.IsPaused(apmServer.ObjectMeta) {
-		log.Info("Paused : skipping reconciliation", "iteration", currentIteration)
+		log.Info("Object is paused. Skipping reconciliation", "namespace", apmServer.Namespace, "as_name", apmServer.Name, "iteration", currentIteration)
 		return common.PauseRequeue, nil
 	}
 
@@ -247,14 +247,14 @@ func (r *ReconcileApmServerElasticsearchAssociation) reconcileInternal(apmServer
 	// TODO: this is a bit rough
 	if !reflect.DeepEqual(apmServer.Spec.Output.Elasticsearch, expectedEsConfig) {
 		apmServer.Spec.Output.Elasticsearch = expectedEsConfig
-		log.Info("Updating Apm Server spec with Elasticsearch output configuration")
+		log.Info("Updating Apm Server spec with Elasticsearch output configuration", "namespace", apmServer.Namespace, "as_name", apmServer.Name)
 		if err := r.Update(&apmServer); err != nil {
 			return commonv1alpha1.AssociationPending, err
 		}
 	}
 
 	if err := deleteOrphanedResources(r, apmServer); err != nil {
-		log.Error(err, "Error while trying to delete orphaned resources. Continuing.")
+		log.Error(err, "Error while trying to delete orphaned resources. Continuing.", "namespace", apmServer.Namespace, "as_name", apmServer.Name)
 	}
 
 	return commonv1alpha1.AssociationEstablished, nil
@@ -274,7 +274,7 @@ func deleteOrphanedResources(c k8s.Client, apm apmtype.ApmServer) error {
 	for _, s := range secrets.Items {
 		controlledBy := metav1.IsControlledBy(&s, &apm)
 		if controlledBy && !apm.Spec.Output.Elasticsearch.ElasticsearchRef.IsDefined() {
-			log.Info("Deleting", "secret", k8s.ExtractNamespacedName(&s))
+			log.Info("Deleting secret", "namespace", s.Namespace, "secret_name", s.Name, "as_name", apm.Name)
 			if err := c.Delete(&s); err != nil {
 				return err
 			}

operators/pkg/controller/common/annotation/pod.go

@@ -15,6 +15,7 @@ import (
 )
 
 const (
+	// UpdateAnnotation is the name of the annotation applied to pods to force kubelet to resync secrets
 	UpdateAnnotation = "update.k8s.elastic.co/timestamp"
 )
 
@@ -52,10 +53,10 @@ func MarkPodAsUpdated(
 	pod corev1.Pod,
 ) {
 	log.V(1).Info(
-		"Update annotation on pod",
+		"Updating annotation on pod",
 		"annotation", UpdateAnnotation,
 		"namespace", pod.Namespace,
-		"pod", pod.Name,
+		"pod_name", pod.Name,
 	)
 	if pod.Annotations == nil {
 		pod.Annotations = map[string]string{}
@@ -64,12 +65,13 @@ func MarkPodAsUpdated(
 		time.Now().Format(time.RFC3339Nano) // nano should be enough to avoid collisions and keep it readable by a human.
 	if err := c.Update(&pod); err != nil {
 		if errors.IsConflict(err) {
-			log.V(1).Info("Conflict while updating pod annotation")
+			// Conflicts are expected and will be handled on the next reconcile loop, no need to error out here
+			log.V(1).Info("Conflict while updating pod annotation", "namespace", pod.Namespace, "pod_name", pod.Name)
 		} else {
 			log.Error(err, "failed to update pod annotation",
 				"annotation", UpdateAnnotation,
 				"namespace", pod.Namespace,
-				"pod", pod.Name)
+				"pod_name", pod.Name)
 		}
 	}
 }

operators/pkg/controller/common/association/keystore/user_secret.go

@@ -71,11 +71,12 @@ func secureSettingsVolume(
 
 func retrieveUserSecret(c k8s.Client, associated commonv1alpha1.Associated, recorder record.EventRecorder) (*corev1.Secret, bool, error) {
 	secretName := associated.SecureSettings().SecretName
+	namespace := associated.GetNamespace()
 	userSecret := corev1.Secret{}
-	err := c.Get(types.NamespacedName{Namespace: associated.GetNamespace(), Name: secretName}, &userSecret)
+	err := c.Get(types.NamespacedName{Namespace: namespace, Name: secretName}, &userSecret)
 	if err != nil && apierrors.IsNotFound(err) {
 		msg := "Secure settings secret not found"
-		log.Info(msg, "name", secretName)
+		log.Info(msg, "namespace", namespace, "secret_name", secretName)
 		recorder.Event(associated, corev1.EventTypeWarning, events.EventReasonUnexpected, msg+": "+secretName)
 		return nil, false, nil
 	} else if err != nil {

operators/pkg/controller/common/certificates/ca_reconcile.go

@@ -54,7 +54,6 @@ func ReconcileCAForOwner(
 	caType CAType,
 	rotationParams RotationParams,
 ) (*CA, error) {
-	ownerNsn := k8s.ExtractNamespacedName(owner)
 
 	// retrieve current CA secret
 	caInternalSecret := corev1.Secret{}
@@ -67,25 +66,25 @@ func ReconcileCAForOwner(
 		return nil, err
 	}
 	if apierrors.IsNotFound(err) {
-		log.Info("No internal CA certificate Secret found, creating a new one", "owner", ownerNsn, "ca_type", caType)
+		log.Info("No internal CA certificate Secret found, creating a new one", "owner_namespace", owner.GetNamespace(), "owner_name", owner.GetName(), "ca_type", caType)
 		return renewCA(cl, namer, owner, labels, rotationParams.Validity, scheme, caType)
 	}
 
 	// build CA
 	ca := buildCAFromSecret(caInternalSecret)
 	if ca == nil {
-		log.Info("Cannot build CA from secret, creating a new one", "owner", ownerNsn, "ca_type", caType)
+		log.Info("Cannot build CA from secret, creating a new one", "owner_namespace", owner.GetNamespace(), "owner_name", owner.GetName(), "ca_type", caType)
 		return renewCA(cl, namer, owner, labels, rotationParams.Validity, scheme, caType)
 	}
 
 	// renew if cannot reuse
 	if !canReuseCA(ca, rotationParams.RotateBefore) {
-		log.Info("Cannot reuse existing CA, creating a new one", "owner", ownerNsn, "ca_type", caType)
+		log.Info("Cannot reuse existing CA, creating a new one", "owner_namespace", owner.GetNamespace(), "owner_name", owner.GetName(), "ca_type", caType)
 		return renewCA(cl, namer, owner, labels, rotationParams.Validity, scheme, caType)
 	}
 
 	// reuse existing CA
-	log.V(1).Info("Reusing existing CA", "owner", ownerNsn, "ca_type", caType)
+	log.V(1).Info("Reusing existing CA", "owner_namespace", owner.GetNamespace(), "owner_name", owner.GetName(), "ca_type", caType)
 	return ca, nil
 }
 
@@ -138,11 +137,11 @@ func canReuseCA(ca *CA, expirationSafetyMargin time.Duration) bool {
 func certIsValid(cert x509.Certificate, expirationSafetyMargin time.Duration) bool {
 	now := time.Now()
 	if now.Before(cert.NotBefore) {
-		log.Info("CA cert is not valid yet, will create a new one")
+		log.Info("CA cert is not valid yet", "subject", cert.Subject)
 		return false
 	}
 	if now.After(cert.NotAfter.Add(-expirationSafetyMargin)) {
-		log.Info("CA cert expired or soon to expire, will create a new one", "expiration", cert.NotAfter)
+		log.Info("CA cert expired or soon to expire", "subject", cert.Subject, "expiration", cert.NotAfter)
 		return false
 	}
 	return true
@@ -181,7 +180,7 @@ func buildCAFromSecret(caInternalSecret corev1.Secret) *CA {
 	}
 	certs, err := ParsePEMCerts(caBytes)
 	if err != nil {
-		log.Info("Cannot parse PEM cert from CA secret, will create a new one", "err", err)
+		log.Error(err, "Cannot parse PEM cert from CA secret, will create a new one", "namespace", caInternalSecret.Namespace, "secret_name", caInternalSecret.Name)
 		return nil
 	}
 	if len(certs) == 0 {
@@ -190,7 +189,8 @@ func buildCAFromSecret(caInternalSecret corev1.Secret) *CA {
 	if len(certs) > 1 {
 		log.Info(
 			"More than 1 certificate in the CA secret, continuing with the first one",
-			"secret", caInternalSecret.Name,
+			"namespace", caInternalSecret.Namespace,
+			"secret_name", caInternalSecret.Name,
 		)
 	}
 	cert := certs[0]
@@ -201,7 +201,7 @@ func buildCAFromSecret(caInternalSecret corev1.Secret) *CA {
 	}
 	privateKey, err := ParsePEMPrivateKey(privateKeyBytes)
 	if err != nil {
-		log.Info("Cannot parse PEM private key from CA secret, will create a new one", "err", err)
+		log.Error(err, "Cannot parse PEM private key from CA secret, will create a new one", "namespace", caInternalSecret.Namespace, "secret_name", caInternalSecret.Name)
 		return nil
 	}
 	return NewCA(privateKey, cert)

operators/pkg/controller/common/certificates/http/reconcile.go

@@ -9,7 +9,6 @@ import (
 	"crypto/rsa"
 	"crypto/x509"
 	"crypto/x509/pkix"
-	"fmt"
 	"net"
 	"reflect"
 	"strings"
@@ -135,12 +134,12 @@ func reconcileHTTPInternalCertificatesSecret(
 
 	if needsUpdate {
 		if shouldCreateSecret {
-			log.Info("Creating HTTP internal certificate secret", "secret", secret.Name)
+			log.Info("Creating HTTP internal certificate secret", "namespace", secret.Namespace, "secret_name", secret.Name)
 			if err := c.Create(&secret); err != nil {
 				return nil, err
 			}
 		} else {
-			log.Info("Updating HTTP internal certificate secret", "secret", secret.Name)
+			log.Info("Updating HTTP internal certificate secret", "namespace", secret.Namespace, "secret_name", secret.Name)
 			if err := c.Update(&secret); err != nil {
 				return nil, err
 			}
@@ -172,7 +171,7 @@ func ensureInternalSelfSignedCertificateSecretContents(
 	if privateKeyData, ok := secret.Data[certificates.KeyFileName]; ok {
 		storedPrivateKey, err := certificates.ParsePEMPrivateKey(privateKeyData)
 		if err != nil {
-			log.Error(err, "Unable to parse stored private key", "secret", secret.Name)
+			log.Error(err, "Unable to parse stored private key", "namespace", secret.Namespace, "secret_name", secret.Name)
 		} else {
 			needsNewPrivateKey = false
 			privateKey = storedPrivateKey
@@ -195,9 +194,10 @@ func ensureInternalSelfSignedCertificateSecretContents(
 	if shouldIssueNewHTTPCertificate(owner, namer, tls, secret, svcs, ca, rotationParam.RotateBefore) {
 		log.Info(
 			"Issuing new HTTP certificate",
-			"secret", secret.Name,
-			"namespace", owner.Namespace,
-			"name", owner.Name,
+			"namespace", secret.Namespace,
+			"secret_name", secret.Name,
+			"owner_namespace", owner.Namespace,
+			"owner_name", owner.Name,
 		)
 
 		csr, err := x509.CreateCertificateRequest(cryptorand.Reader, &x509.CertificateRequest{}, privateKey)
@@ -263,7 +263,7 @@ func shouldIssueNewHTTPCertificate(
 	} else {
 		certs, err := certificates.ParsePEMCerts(certData)
 		if err != nil {
-			log.Error(err, "Invalid certificate data found, issuing new certificate", "secret", secret.Name)
+			log.Error(err, "Invalid certificate data found, issuing new certificate", "namespace", secret.Namespace, "secret_name", secret.Name)
 			return true
 		}
 
@@ -289,16 +289,20 @@ func shouldIssueNewHTTPCertificate(
 	}
 	if _, err := certificate.Verify(verifyOpts); err != nil {
 		log.Info(
-			fmt.Sprintf("Certificate was not valid, should issue new: %s", err),
+			"Certificate was not valid, should issue new",
+			"validation_failure", err,
 			"subject", certificate.Subject,
 			"issuer", certificate.Issuer,
 			"current_ca_subject", ca.Cert.Subject,
+			"secret_name", secret.Name,
+			"namespace", secret.Namespace,
+			"owner_name", owner.Name,
 		)
 		return true
 	}
 
 	if time.Now().After(certificate.NotAfter.Add(-certReconcileBefore)) {
-		log.Info("Certificate soon to expire, should issue new", "secret", secret.Name)
+		log.Info("Certificate soon to expire, should issue new", "namespace", secret.Namespace, "secret_name", secret.Name)
 		return true
 	}
 

operators/pkg/controller/common/certificates/x509_othername.go

@@ -8,7 +8,6 @@ import (
 	"crypto/x509"
 	"encoding/asn1"
 	"errors"
-	"fmt"
 
 	logf "sigs.k8s.io/controller-runtime/pkg/runtime/log"
 )
@@ -209,7 +208,7 @@ func ParseSANGeneralNamesOtherNamesOnly(c *x509.Certificate) ([]GeneralName, err
 							},
 						})
 					default:
-						log.Info(fmt.Sprintf("Ignoring unsupported GeneralNames tag [%d]", generalName.Tag))
+						log.Info("Ignoring unsupported GeneralNames tag", "tag", generalName.Tag, "subject", c.Subject)
 					}
 				}
 			}

operators/pkg/controller/common/finalizer/handler.go

@@ -49,7 +49,7 @@ func (h *Handler) Handle(resource runtime.Object, finalizers ...Finalizer) error
 	var finalizerErr error
 	if metaObject.GetDeletionTimestamp().IsZero() {
 		// resource is not being deleted, make sure all finalizers are there
-		needUpdate = h.reconcileFinalizers(finalizers, metaObject, resource)
+		needUpdate = h.reconcileFinalizers(finalizers, metaObject)
 	} else {
 		// resource is being deleted, let's execute finalizers
 		needUpdate, finalizerErr = h.executeFinalizers(finalizers, metaObject, resource)
@@ -62,15 +62,14 @@ func (h *Handler) Handle(resource runtime.Object, finalizers ...Finalizer) error
 	return finalizerErr
 }
 
-// ReconcileFinalizers makes sure all finalizers exist in the given objectMeta.
-// If some finalizers need to be added to objectMeta,
-// an update to the apiserver will be issued for the given resource.
-func (h *Handler) reconcileFinalizers(finalizers []Finalizer, object metav1.Object, resource runtime.Object) bool {
+// reconcileFinalizers ensures all finalizers exist in the given objectMeta.
+// Returns a bool indicating if an update is required to the object
+func (h *Handler) reconcileFinalizers(finalizers []Finalizer, object metav1.Object) bool {
 	needUpdate := false
 	for _, finalizer := range finalizers {
 		// add finalizer if not already there
 		if !stringsutil.StringInSlice(finalizer.Name, object.GetFinalizers()) {
-			log.Info("Registering finalizer", "name", finalizer.Name)
+			log.Info("Registering finalizer", "finalizer_name", finalizer.Name, "namespace", object.GetNamespace(), "name", object.GetName())
 			object.SetFinalizers(append(object.GetFinalizers(), finalizer.Name))
 			needUpdate = true
 		}
@@ -87,7 +86,7 @@ func (h *Handler) executeFinalizers(finalizers []Finalizer, object metav1.Object
 	for _, finalizer := range finalizers {
 		// for each registered finalizer, execute it, then remove from the list
 		if stringsutil.StringInSlice(finalizer.Name, object.GetFinalizers()) {
-			log.Info("Executing finalizer", "name", finalizer.Name)
+			log.Info("Executing finalizer", "finalizer_name", finalizer.Name, "namespace", object.GetNamespace(), "name", object.GetName())
 			if finalizerErr = finalizer.Execute(); finalizerErr != nil {
 				break
 			}