Skip to content

Commit

Permalink
Switch to structured logging
Browse files Browse the repository at this point in the history
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
  • Loading branch information
pinikomarov committed Oct 17, 2023
1 parent f35f8a5 commit 4ba5c0d
Show file tree
Hide file tree
Showing 23 changed files with 108 additions and 63 deletions.
20 changes: 13 additions & 7 deletions controllers/client/openstackclient_controller.go
Original file line number Diff line number Diff line change
Expand Up @@ -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"
condition "github.com/openstack-k8s-operators/lib-common/modules/common/condition"
Expand All @@ -45,7 +46,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
Expand All @@ -64,18 +69,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(
Expand All @@ -92,7 +98,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
Expand Down Expand Up @@ -151,7 +157,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(
Expand All @@ -168,7 +174,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
}

Expand Down
20 changes: 11 additions & 9 deletions controllers/core/openstackcontrolplane_controller.go
Original file line number Diff line number Diff line change
Expand Up @@ -18,7 +18,6 @@ package core

import (
"context"
"fmt"

routev1 "github.com/openshift/api/route/v1"
cinderv1 "github.com/openstack-k8s-operators/cinder-operator/api/v1beta1"
Expand Down Expand Up @@ -47,22 +46,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
Expand Down Expand Up @@ -101,8 +103,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)
Expand All @@ -111,7 +113,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.
Expand All @@ -123,11 +125,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
}

Expand Down
3 changes: 1 addition & 2 deletions main.go
Original file line number Diff line number Diff line change
Expand Up @@ -116,7 +116,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,
Expand Down Expand Up @@ -166,7 +166,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)
Expand Down
6 changes: 4 additions & 2 deletions pkg/openstack/ceilometer.go
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand All @@ -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)

Expand All @@ -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() {
Expand Down
5 changes: 3 additions & 2 deletions pkg/openstack/cinder.go
Original file line number Diff line number Diff line change
Expand Up @@ -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} {
Expand Down Expand Up @@ -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)

Expand Down Expand Up @@ -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() {
Expand Down
7 changes: 7 additions & 0 deletions pkg/openstack/common.go
Original file line number Diff line number Diff line change
Expand Up @@ -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/common"
"github.com/openstack-k8s-operators/lib-common/modules/common/condition"
Expand All @@ -19,8 +20,14 @@ 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"
)

// 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)
Expand Down
6 changes: 4 additions & 2 deletions pkg/openstack/dnsmasq.go
Original file line number Diff line number Diff line change
Expand Up @@ -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 {
Expand All @@ -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() {
Expand Down
5 changes: 3 additions & 2 deletions pkg/openstack/galera.go
Original file line number Diff line number Diff line change
Expand Up @@ -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 {
Expand All @@ -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())
Expand All @@ -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() {
Expand Down
6 changes: 4 additions & 2 deletions pkg/openstack/glance.go
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down Expand Up @@ -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])
Expand Down Expand Up @@ -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() {
Expand Down
6 changes: 4 additions & 2 deletions pkg/openstack/heat.go
Original file line number Diff line number Diff line change
Expand Up @@ -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)

Expand All @@ -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() {
Expand Down
5 changes: 3 additions & 2 deletions pkg/openstack/horizon.go
Original file line number Diff line number Diff line change
Expand Up @@ -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 {
Expand Down Expand Up @@ -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])
Expand All @@ -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() {
Expand Down
5 changes: 3 additions & 2 deletions pkg/openstack/ironic.go
Original file line number Diff line number Diff line change
Expand Up @@ -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 {
Expand Down Expand Up @@ -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())
Expand All @@ -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() {
Expand Down
Loading

0 comments on commit 4ba5c0d

Please sign in to comment.