Switch to structured logging

This automatically adds additional Log fields like reconcile_id etc.. from the controller context. Follow up from: openstack-k8s-operators/keystone-operator#220 Epic : [OSP-22582](https://issues.redhat.com/browse/OSP-22582) Switch Operators to structured logging before : ```bash {"level":"info","ts":"2023-07-04T10:11:14.655+0300","logger":"controllers.OpenStackControlPlane","msg":"Reconciling Glance","Glance.Namespace":"openstack","Glance.Name":"glance"} ``` after: ```bash 2023-07-04T16:37:17.388+0300 INFO Controllers.OpenstackControlPlane Reconciling Cinder {"controller": "openstackcontrolplane", "controllerGroup": "core.openstack.org", "controllerKind": "OpenStackControlPlane", "OpenStackControlPlane": {"name":"openstack-network-isolation","namespace":"openstack"}, "namespace": "openstack", "name": "openstack-network-isolation", "reconcileID": "4801c762-5a50-4773-849c-c8b19f59841d", "Cinder.Namespace": "openstack", "Cinder.Name": "cinder"} ``` Full logs with before and after log messages for the multiple resources called by this operator: Full Before : http://pastebin.test.redhat.com/1104088 Full After: http://pastebin.test.redhat.com/1104132 set log dev true for console output fix non needed fmt import update logging usage update logging naming update main.go logging update logging fixup
openstack-k8s-operators · Nov 4, 2023 · 46df8c0 · 46df8c0
1 parent 8c479ca
commit 46df8c0
Show file tree

Hide file tree

Showing 24 changed files with 108 additions and 65 deletions.
diff --git a/controllers/client/openstackclient_controller.go b/controllers/client/openstackclient_controller.go
@@ -28,6 +28,7 @@ import (
 	ctrl "sigs.k8s.io/controller-runtime"
 	"sigs.k8s.io/controller-runtime/pkg/client"
 	"sigs.k8s.io/controller-runtime/pkg/controller/controllerutil"
+	"sigs.k8s.io/controller-runtime/pkg/log"
 
 	keystonev1 "github.com/openstack-k8s-operators/keystone-operator/api/v1beta1"
 	"github.com/openstack-k8s-operators/lib-common/modules/common"
@@ -47,7 +48,11 @@ type OpenStackClientReconciler struct {
 	client.Client
 	Scheme  *runtime.Scheme
 	Kclient kubernetes.Interface
-	Log     logr.Logger
+}
+
+// GetLog returns a logger object with a prefix of "conroller.name" and aditional controller context fields
+func (r *OpenStackClientReconciler) GetLogger(ctx context.Context) logr.Logger {
+	return log.FromContext(ctx).WithName("Controllers").WithName("OpenStackClient")
 }
 
 //+kubebuilder:rbac:groups=client.openstack.org,resources=openstackclients,verbs=get;list;watch;create;update;patch;delete
@@ -66,18 +71,19 @@ type OpenStackClientReconciler struct {
 
 // Reconcile -
 func (r *OpenStackClientReconciler) Reconcile(ctx context.Context, req ctrl.Request) (result ctrl.Result, _err error) {
-	_ = r.Log.WithValues("openstackclient", req.NamespacedName)
+
+	Log := r.GetLogger(ctx)
 
 	instance := &clientv1.OpenStackClient{}
 	err := r.Client.Get(context.TODO(), req.NamespacedName, instance)
 	if err != nil {
 		if k8s_errors.IsNotFound(err) {
-			r.Log.Info("OpenStackClient CR not found", "Name", instance.Name, "Namespace", instance.Namespace)
+			Log.Info("OpenStackClient CR not found", "Name", instance.Name, "Namespace", instance.Namespace)
 			return ctrl.Result{}, nil
 		}
 		return ctrl.Result{}, err
 	}
-	r.Log.Info("OpenStackClient CR values", "Name", instance.Name, "Namespace", instance.Namespace, "Secret", instance.Spec.OpenStackConfigSecret, "Image", instance.Spec.ContainerImage)
+	Log.Info("OpenStackClient CR values", "Name", instance.Name, "Namespace", instance.Namespace, "Secret", instance.Spec.OpenStackConfigSecret, "Image", instance.Spec.ContainerImage)
 
 	instance.Status.Conditions = condition.Conditions{}
 	cl := condition.CreateList(
@@ -94,7 +100,7 @@ func (r *OpenStackClientReconciler) Reconcile(ctx context.Context, req ctrl.Requ
 		r.Client,
 		r.Kclient,
 		r.Scheme,
-		r.Log,
+		Log,
 	)
 	if err != nil {
 		return ctrl.Result{}, err
@@ -153,7 +159,7 @@ func (r *OpenStackClientReconciler) Reconcile(ctx context.Context, req ctrl.Requ
 				condition.RequestedReason,
 				condition.SeverityInfo,
 				clientv1.OpenStackClientKeystoneWaitingMessage))
-			r.Log.Info("KeystoneAPI not found!")
+			Log.Info("KeystoneAPI not found!")
 			return ctrl.Result{RequeueAfter: time.Duration(5) * time.Second}, nil
 		}
 		instance.Status.Conditions.Set(condition.FalseCondition(
@@ -170,7 +176,7 @@ func (r *OpenStackClientReconciler) Reconcile(ctx context.Context, req ctrl.Requ
 			condition.RequestedReason,
 			condition.SeverityInfo,
 			clientv1.OpenStackClientKeystoneWaitingMessage))
-		r.Log.Info("KeystoneAPI not yet ready")
+		Log.Info("KeystoneAPI not yet ready")
 		return ctrl.Result{RequeueAfter: time.Duration(5) * time.Second}, nil
 	}
 

diff --git a/controllers/core/openstackcontrolplane_controller.go b/controllers/core/openstackcontrolplane_controller.go
@@ -18,7 +18,6 @@ package core
 
 import (
 	"context"
-	"fmt"
 
 	certmgrv1 "github.com/cert-manager/cert-manager/pkg/apis/certmanager/v1"
 	routev1 "github.com/openshift/api/route/v1"
@@ -50,22 +49,25 @@ import (
 	telemetryv1 "github.com/openstack-k8s-operators/telemetry-operator/api/v1beta1"
 	rabbitmqv2 "github.com/rabbitmq/cluster-operator/v2/api/v1beta1"
 
+	"github.com/go-logr/logr"
+	k8s_errors "k8s.io/apimachinery/pkg/api/errors"
 	"k8s.io/apimachinery/pkg/runtime"
 	"k8s.io/client-go/kubernetes"
 	ctrl "sigs.k8s.io/controller-runtime"
 	"sigs.k8s.io/controller-runtime/pkg/client"
 	"sigs.k8s.io/controller-runtime/pkg/log"
-
-	"github.com/go-logr/logr"
-	k8s_errors "k8s.io/apimachinery/pkg/api/errors"
 )
 
 // OpenStackControlPlaneReconciler reconciles a OpenStackControlPlane object
 type OpenStackControlPlaneReconciler struct {
 	client.Client
 	Scheme  *runtime.Scheme
 	Kclient kubernetes.Interface
-	Log     logr.Logger
+}
+
+// GetLog returns a logger object with a prefix of "conroller.name" and aditional controller context fields
+func (r *OpenStackControlPlaneReconciler) GetLogger(ctx context.Context) logr.Logger {
+	return log.FromContext(ctx).WithName("Controllers").WithName("OpenStackControlPlane")
 }
 
 //+kubebuilder:rbac:groups=core.openstack.org,resources=openstackcontrolplanes,verbs=get;list;watch;create;update;patch;delete
@@ -107,8 +109,8 @@ type OpenStackControlPlaneReconciler struct {
 // For more details, check Reconcile and its Result here:
 // - https://pkg.go.dev/sigs.k8s.io/[email protected]/pkg/reconcile
 func (r *OpenStackControlPlaneReconciler) Reconcile(ctx context.Context, req ctrl.Request) (result ctrl.Result, _err error) {
-	_ = log.FromContext(ctx)
 
+	Log := r.GetLogger(ctx)
 	// Fetch the OpenStackControlPlane instance
 	instance := &corev1beta1.OpenStackControlPlane{}
 	err := r.Client.Get(ctx, req.NamespacedName, instance)
@@ -117,7 +119,7 @@ func (r *OpenStackControlPlaneReconciler) Reconcile(ctx context.Context, req ctr
 			// Request object not found, could have been deleted after reconcile request.
 			// Owned objects are automatically garbage collected.
 			// For additional cleanup logic use finalizers. Return and don't requeue.
-			r.Log.Info("OpenStackControlPlane instance is not found, probaby deleted. Nothing to do.")
+			Log.Info("OpenStackControlPlane instance is not found, probaby deleted. Nothing to do.")
 			return ctrl.Result{}, nil
 		}
 		// Error reading the object - requeue the request.
@@ -129,11 +131,11 @@ func (r *OpenStackControlPlaneReconciler) Reconcile(ctx context.Context, req ctr
 		r.Client,
 		r.Kclient,
 		r.Scheme,
-		r.Log,
+		Log,
 	)
 	if err != nil {
 		// helper might be nil, so can't use util.LogErrorForObject since it requires helper as first arg
-		r.Log.Error(err, fmt.Sprintf("unable to acquire helper for OpenStackControlPlane %s", instance.Name))
+		Log.Error(err, "unable to acquire helper for OpenStackControlPlane")
 		return ctrl.Result{}, err
 	}
 

diff --git a/main.go b/main.go
@@ -118,7 +118,7 @@ func main() {
 			"Enabling this will ensure there is only one active controller manager.")
 	devMode, err := strconv.ParseBool(os.Getenv("DEV_MODE"))
 	if err != nil {
-		devMode = false
+		devMode = true
 	}
 	opts := zap.Options{
 		Development: devMode,
@@ -168,7 +168,6 @@ func main() {
 		Client:  mgr.GetClient(),
 		Scheme:  mgr.GetScheme(),
 		Kclient: kclient,
-		Log:     ctrl.Log.WithName("controllers").WithName("OpenStackControlPlane"),
 	}).SetupWithManager(mgr); err != nil {
 		setupLog.Error(err, "unable to create controller", "controller", "OpenStackControlPlane")
 		os.Exit(1)

diff --git a/pkg/openstack/ceilometer.go b/pkg/openstack/ceilometer.go
@@ -30,6 +30,8 @@ func ReconcileCeilometer(ctx context.Context, instance *corev1beta1.OpenStackCon
 		},
 	}
 
+	Log := GetLogger(ctx)
+
 	if !instance.Spec.Ceilometer.Enabled {
 		if res, err := EnsureDeleted(ctx, helper, ceilometer); err != nil {
 			return res, err
@@ -38,7 +40,7 @@ func ReconcileCeilometer(ctx context.Context, instance *corev1beta1.OpenStackCon
 		return ctrl.Result{}, nil
 	}
 
-	helper.GetLogger().Info("Reconciling Ceilometer", ceilometerNamespaceLabel, instance.Namespace, ceilometerNameLabel, ceilometerName)
+	Log.Info("Reconciling Ceilometer", ceilometerNamespaceLabel, instance.Namespace, ceilometerNameLabel, ceilometerName)
 	op, err := controllerutil.CreateOrPatch(ctx, helper.GetClient(), ceilometer, func() error {
 		instance.Spec.Ceilometer.Template.DeepCopyInto(&ceilometer.Spec)
 
@@ -63,7 +65,7 @@ func ReconcileCeilometer(ctx context.Context, instance *corev1beta1.OpenStackCon
 		return ctrl.Result{}, err
 	}
 	if op != controllerutil.OperationResultNone {
-		helper.GetLogger().Info(fmt.Sprintf("%s %s - %s", ceilometerName, ceilometer.Name, op))
+		Log.Info(fmt.Sprintf("%s %s - %s", ceilometerName, ceilometer.Name, op))
 	}
 
 	if ceilometer.IsReady() {

diff --git a/pkg/openstack/cinder.go b/pkg/openstack/cinder.go
@@ -37,6 +37,7 @@ func ReconcileCinder(ctx context.Context, instance *corev1beta1.OpenStackControl
 		instance.Status.Conditions.Remove(corev1beta1.OpenStackControlPlaneExposeCinderReadyCondition)
 		return ctrl.Result{}, nil
 	}
+	Log := GetLogger(ctx)
 
 	// add selector to service overrides
 	for _, endpointType := range []service.Endpoint{service.EndpointPublic, service.EndpointInternal} {
@@ -85,7 +86,7 @@ func ReconcileCinder(ctx context.Context, instance *corev1beta1.OpenStackControl
 		}
 	}
 
-	helper.GetLogger().Info("Reconciling Cinder", "Cinder.Namespace", instance.Namespace, "Cinder.Name", "cinder")
+	Log.Info("Reconciling Cinder", "Cinder.Namespace", instance.Namespace, "Cinder.Name", "cinder")
 	op, err := controllerutil.CreateOrPatch(ctx, helper.GetClient(), cinder, func() error {
 		instance.Spec.Cinder.Template.DeepCopyInto(&cinder.Spec)
 
@@ -131,7 +132,7 @@ func ReconcileCinder(ctx context.Context, instance *corev1beta1.OpenStackControl
 		return ctrl.Result{}, err
 	}
 	if op != controllerutil.OperationResultNone {
-		helper.GetLogger().Info(fmt.Sprintf("Cinder %s - %s", cinder.Name, op))
+		Log.Info(fmt.Sprintf("Cinder %s - %s", cinder.Name, op))
 	}
 
 	if cinder.IsReady() {

diff --git a/pkg/openstack/common.go b/pkg/openstack/common.go
@@ -5,6 +5,7 @@ import (
 	"fmt"
 	"time"
 
+	"github.com/go-logr/logr"
 	routev1 "github.com/openshift/api/route/v1"
 	"github.com/openstack-k8s-operators/lib-common/modules/certmanager"
 	"github.com/openstack-k8s-operators/lib-common/modules/common"
@@ -23,9 +24,15 @@ import (
 	"k8s.io/utils/ptr"
 	ctrl "sigs.k8s.io/controller-runtime"
 	"sigs.k8s.io/controller-runtime/pkg/client"
+	"sigs.k8s.io/controller-runtime/pkg/log"
 	"sigs.k8s.io/controller-runtime/pkg/reconcile"
 )
 
+// GetLog returns a logger object with a prefix of "controller.name" and aditional controller context fields
+func GetLogger(ctx context.Context) logr.Logger {
+	return log.FromContext(ctx).WithName("Controllers").WithName("OpenstackControlPlane")
+}
+
 // EnsureDeleted - Delete the object which in turn will clean the sub resources
 func EnsureDeleted(ctx context.Context, helper *helper.Helper, obj client.Object) (ctrl.Result, error) {
 	key := client.ObjectKeyFromObject(obj)

diff --git a/pkg/openstack/dnsmasq.go b/pkg/openstack/dnsmasq.go
@@ -33,7 +33,9 @@ func ReconcileDNSMasqs(ctx context.Context, instance *corev1beta1.OpenStackContr
 		return ctrl.Result{}, nil
 	}
 
-	helper.GetLogger().Info("Reconciling DNSMasq", "DNSMasq.Namespace", instance.Namespace, "DNSMasq.Name", "dnsmasq")
+	Log := GetLogger(ctx)
+
+	Log.Info("Reconciling DNSMasq", "DNSMasq.Namespace", instance.Namespace, "DNSMasq.Name", "dnsmasq")
 	op, err := controllerutil.CreateOrPatch(ctx, helper.GetClient(), dnsmasq, func() error {
 		instance.Spec.DNS.Template.DeepCopyInto(&dnsmasq.Spec)
 		if dnsmasq.Spec.NodeSelector == nil && instance.Spec.NodeSelector != nil {
@@ -56,7 +58,7 @@ func ReconcileDNSMasqs(ctx context.Context, instance *corev1beta1.OpenStackContr
 		return ctrl.Result{}, err
 	}
 	if op != controllerutil.OperationResultNone {
-		helper.GetLogger().Info(fmt.Sprintf("dnsmasq %s - %s", dnsmasq.Name, op))
+		Log.Info(fmt.Sprintf("dnsmasq %s - %s", dnsmasq.Name, op))
 	}
 
 	if dnsmasq.IsReady() {

diff --git a/pkg/openstack/galera.go b/pkg/openstack/galera.go
@@ -93,6 +93,7 @@ func reconcileGalera(
 			Namespace: instance.Namespace,
 		},
 	}
+	Log := GetLogger(ctx)
 
 	if !instance.Spec.Galera.Enabled {
 		if _, err := EnsureDeleted(ctx, helper, galera); err != nil {
@@ -102,7 +103,7 @@ func reconcileGalera(
 		return galeraReady, nil
 	}
 
-	helper.GetLogger().Info("Reconciling Galera", "Galera.Namespace", instance.Namespace, "Galera.Name", name)
+	Log.Info("Reconciling Galera", "Galera.Namespace", instance.Namespace, "Galera.Name", name)
 	op, err := controllerutil.CreateOrPatch(ctx, helper.GetClient(), galera, func() error {
 		spec.DeepCopyInto(&galera.Spec)
 		err := controllerutil.SetControllerReference(helper.GetBeforeObject(), galera, helper.GetScheme())
@@ -117,7 +118,7 @@ func reconcileGalera(
 		return galeraFailed, err
 	}
 	if op != controllerutil.OperationResultNone {
-		helper.GetLogger().Info(fmt.Sprintf("Galera %s - %s", galera.Name, op))
+		Log.Info(fmt.Sprintf("Galera %s - %s", galera.Name, op))
 	}
 
 	if galera.IsReady() {

diff --git a/pkg/openstack/glance.go b/pkg/openstack/glance.go
@@ -30,6 +30,8 @@ func ReconcileGlance(ctx context.Context, instance *corev1beta1.OpenStackControl
 		},
 	}
 
+	Log := GetLogger(ctx)
+
 	if !instance.Spec.Glance.Enabled {
 		if res, err := EnsureDeleted(ctx, helper, glance); err != nil {
 			return res, err
@@ -89,7 +91,7 @@ func ReconcileGlance(ctx context.Context, instance *corev1beta1.OpenStackControl
 		}
 	}
 
-	helper.GetLogger().Info("Reconciling Glance", "Glance.Namespace", instance.Namespace, "Glance.Name", "glance")
+	Log.Info("Reconciling Glance", "Glance.Namespace", instance.Namespace, "Glance.Name", "glance")
 	op, err := controllerutil.CreateOrPatch(ctx, helper.GetClient(), glance, func() error {
 		instance.Spec.Glance.Template.DeepCopyInto(&glance.Spec)
 		glance.Spec.GlanceAPIExternal.Override.Service = ptr.To(serviceOverrides[service.EndpointPublic])
@@ -136,7 +138,7 @@ func ReconcileGlance(ctx context.Context, instance *corev1beta1.OpenStackControl
 		return ctrl.Result{}, err
 	}
 	if op != controllerutil.OperationResultNone {
-		helper.GetLogger().Info(fmt.Sprintf("glance %s - %s", glance.Name, op))
+		Log.Info(fmt.Sprintf("glance %s - %s", glance.Name, op))
 	}
 
 	if glance.IsReady() {

diff --git a/pkg/openstack/heat.go b/pkg/openstack/heat.go
@@ -124,7 +124,9 @@ func ReconcileHeat(ctx context.Context, instance *corev1beta1.OpenStackControlPl
 		}
 	}
 
-	helper.GetLogger().Info("Reconcile heat", "heat.Namespace", instance.Namespace, "heat.Name", "heat")
+	Log := GetLogger(ctx)
+
+	Log.Info("Reconcile heat", "heat.Namespace", instance.Namespace, "heat.Name", "heat")
 	op, err := controllerutil.CreateOrPatch(ctx, helper.GetClient(), heat, func() error {
 		instance.Spec.Heat.Template.DeepCopyInto(&heat.Spec)
 
@@ -145,7 +147,7 @@ func ReconcileHeat(ctx context.Context, instance *corev1beta1.OpenStackControlPl
 		return ctrl.Result{}, err
 	}
 	if op != controllerutil.OperationResultNone {
-		helper.GetLogger().Info(fmt.Sprintf("heat %s - %s", heat.Name, op))
+		Log.Info(fmt.Sprintf("heat %s - %s", heat.Name, op))
 	}
 
 	if heat.IsReady() {

diff --git a/pkg/openstack/horizon.go b/pkg/openstack/horizon.go
@@ -29,6 +29,7 @@ func ReconcileHorizon(ctx context.Context, instance *corev1beta1.OpenStackContro
 			Namespace: instance.Namespace,
 		},
 	}
+	Log := GetLogger(ctx)
 
 	if !instance.Spec.Horizon.Enabled {
 		if res, err := EnsureDeleted(ctx, helper, horizon); err != nil {
@@ -96,7 +97,7 @@ func ReconcileHorizon(ctx context.Context, instance *corev1beta1.OpenStackContro
 		}
 	}
 
-	helper.GetLogger().Info("Reconcile Horizon", "horizon.Namespace", instance.Namespace, "horizon.Name", "horizon")
+	Log.Info("Reconcile Horizon", "horizon.Namespace", instance.Namespace, "horizon.Name", "horizon")
 	op, err := controllerutil.CreateOrPatch(ctx, helper.GetClient(), horizon, func() error {
 		instance.Spec.Horizon.Template.DeepCopyInto(&horizon.Spec)
 		horizon.Spec.Override.Service = ptr.To(serviceOverrides[service.EndpointPublic])
@@ -118,7 +119,7 @@ func ReconcileHorizon(ctx context.Context, instance *corev1beta1.OpenStackContro
 		return ctrl.Result{}, err
 	}
 	if op != controllerutil.OperationResultNone {
-		helper.GetLogger().Info(fmt.Sprintf("Horizon %s - %s", horizon.Name, op))
+		Log.Info(fmt.Sprintf("Horizon %s - %s", horizon.Name, op))
 	}
 
 	if horizon.IsReady() {

diff --git a/pkg/openstack/ironic.go b/pkg/openstack/ironic.go
@@ -28,6 +28,7 @@ func ReconcileIronic(ctx context.Context, instance *corev1beta1.OpenStackControl
 			Namespace: instance.Namespace,
 		},
 	}
+	Log := GetLogger(ctx)
 
 	if !instance.Spec.Ironic.Enabled {
 		if res, err := EnsureDeleted(ctx, helper, ironic); err != nil {
@@ -124,7 +125,7 @@ func ReconcileIronic(ctx context.Context, instance *corev1beta1.OpenStackControl
 		}
 	}
 
-	helper.GetLogger().Info("Reconciling Ironic", "Ironic.Namespace", instance.Namespace, "Ironic.Name", "ironic")
+	Log.Info("Reconciling Ironic", "Ironic.Namespace", instance.Namespace, "Ironic.Name", "ironic")
 	op, err := controllerutil.CreateOrPatch(ctx, helper.GetClient(), ironic, func() error {
 		instance.Spec.Ironic.Template.DeepCopyInto(&ironic.Spec)
 		err := controllerutil.SetControllerReference(helper.GetBeforeObject(), ironic, helper.GetScheme())
@@ -144,7 +145,7 @@ func ReconcileIronic(ctx context.Context, instance *corev1beta1.OpenStackControl
 		return ctrl.Result{}, err
 	}
 	if op != controllerutil.OperationResultNone {
-		helper.GetLogger().Info(fmt.Sprintf("ironic %s - %s", ironic.Name, op))
+		Log.Info(fmt.Sprintf("ironic %s - %s", ironic.Name, op))
 	}
 
 	if ironic.IsReady() {