Skip to content

Commit

Permalink
switch to structured logging
Browse files Browse the repository at this point in the history 
This automatically adds additional fields like reconcile_id etc.. from the controller context.

before :

2023-05-18T01:53:14+03:00 INFO  controllers.KeystoneAPI Reconciled Service init successfully

after:

2023-10-04T16:06:31+03:00       INFO    Controllers.CinderAPI   Reconciled Service 'cinder-api' successfully    {"controller": "cinderapi", "controllerGroup": "cinder.openstack.org", "controllerKind": "CinderAPI", "CinderAPI": {"name":"cinder-api","namespace":"openstack"}, "namespace": "openstack", "name": "cinder-api", "reconcileID": "09fed477-8ad5-4186-8b20-790f409de78a"}

*by using per reconcile function respective logger objects, the intention is to lay the ground for parallel reconciliation in future and avoid race conditions as ctx objects are reconcile run specific.

fix logging implementations

update correct controller name

use single controller name in top logger func

set controler unique log func name

fix log usage in scheduler

add top level ctx

use propogated ctx from main in controllers

use struct method for same logger signiture in controllers

use struct method for same logger signiture in controllers

getlog->GetLogger

sed log->Log

update logging

switch to structured logging

This automatically adds additional fields like reconcile_id etc.. from the controller context.

before :

2023-05-18T01:53:14+03:00 INFO  controllers.KeystoneAPI Reconciled Service init successfully

after:

2023-10-04T16:06:31+03:00       INFO    Controllers.CinderAPI   Reconciled Service 'cinder-api' successfully    {"controller": "cinderapi", "controllerGroup": "cinder.openstack.org", "controllerKind": "CinderAPI", "CinderAPI": {"name":"cinder-api","namespace":"openstack"}, "namespace": "openstack", "name": "cinder-api", "reconcileID": "09fed477-8ad5-4186-8b20-790f409de78a"}

*by using per reconcile function respective logger objects, the intention is to lay the ground for parallel reconciliation in future and avoid race conditions as ctx objects are reconcile run specific.

fix logging implementations

update correct controller name

use single controller name in top logger func

set controler unique log func name

fix log usage in scheduler

add top level ctx

use propogated ctx from main in controllers

use struct method for same logger signiture in controllers

use struct method for same logger signiture in controllers

getlog->GetLogger

sed log->Log

update logging

Structured logging
  • Loading branch information
@pinikomarov
pinikomarov committed Nov 8, 2023
1 parent 48a662e commit 52d9e8d
Show file tree
Hide file tree
Showing 6 changed files with 224 additions and 136 deletions.
100 changes: 71 additions & 29 deletions controllers/cinder_controller.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -66,9 +66,9 @@ func (r *CinderReconciler) GetKClient() kubernetes.Interface {
return r.Kclient
}

// GetLogger -
func (r *CinderReconciler) GetLogger() logr.Logger {
return r.Log
// GetLogger returns a logger object with a logging prefix of "controllers.name" and additional controller context fields
func (r *CinderReconciler) GetLogger(ctx context.Context) logr.Logger {
return log.FromContext(ctx).WithName("Controllers").WithName("Cinder")
}

// GetScheme -
Expand All @@ -80,7 +80,6 @@ func (r *CinderReconciler) GetScheme() *runtime.Scheme {
type CinderReconciler struct {
client.Client
Kclient kubernetes.Interface
Log logr.Logger
Scheme *runtime.Scheme
}

Expand Down Expand Up @@ -116,7 +115,7 @@ type CinderReconciler struct {

// Reconcile -
func (r *CinderReconciler) Reconcile(ctx context.Context, req ctrl.Request) (result ctrl.Result, _err error) {
_ = log.FromContext(ctx)
Log := r.GetLogger(ctx)

// Fetch the Cinder instance
instance := &cinderv1beta1.Cinder{}
Expand All @@ -137,7 +136,7 @@ func (r *CinderReconciler) Reconcile(ctx context.Context, req ctrl.Request) (res
r.Client,
r.Kclient,
r.Scheme,
r.Log,
Log,
)
if err != nil {
return ctrl.Result{}, err
Expand Down Expand Up @@ -211,7 +210,7 @@ func (r *CinderReconciler) Reconcile(ctx context.Context, req ctrl.Request) (res
}

// SetupWithManager sets up the controller with the Manager.
func (r *CinderReconciler) SetupWithManager(mgr ctrl.Manager) error {
func (r *CinderReconciler) SetupWithManager(ctx context.Context, mgr ctrl.Manager) error {
// transportURLSecretFn - Watch for changes made to the secret associated with the RabbitMQ
// TransportURL created and used by Cinder CRs. Watch functions return a list of namespace-scoped
// CRs that then get fed to the reconciler. Hence, in this case, we need to know the name of the
Expand All @@ -222,6 +221,9 @@ func (r *CinderReconciler) SetupWithManager(mgr ctrl.Manager) error {
// matches the name of an existing Cinder CR. In that case changes to that secret would trigger
// reconciliation for a Cinder CR that does not need it.
//

Log := r.GetLogger(ctx)

// TODO: We also need a watch func to monitor for changes to the secret referenced by Cinder.Spec.Secret
transportURLSecretFn := func(o client.Object) []reconcile.Request {
result := []reconcile.Request{}
Expand All @@ -231,8 +233,8 @@ func (r *CinderReconciler) SetupWithManager(mgr ctrl.Manager) error {
listOpts := []client.ListOption{
client.InNamespace(o.GetNamespace()),
}
if err := r.Client.List(context.Background(), cinders, listOpts...); err != nil {
r.Log.Error(err, "Unable to retrieve Cinder CRs %v")
if err := r.Client.List(ctx, cinders, listOpts...); err != nil {
Log.Error(err, "Unable to retrieve Cinder CRs")
return nil
}

Expand All @@ -245,7 +247,7 @@ func (r *CinderReconciler) SetupWithManager(mgr ctrl.Manager) error {
Namespace: o.GetNamespace(),
Name: cr.Name,
}
r.Log.Info(fmt.Sprintf("TransportURL Secret %s belongs to TransportURL belonging to Cinder CR %s", o.GetName(), cr.Name))
Log.Info(fmt.Sprintf("TransportURL Secret %s belongs to TransportURL belonging to Cinder CR %s", o.GetName(), cr.Name))
result = append(result, reconcile.Request{NamespacedName: name})
}
}
Expand All @@ -257,6 +259,35 @@ func (r *CinderReconciler) SetupWithManager(mgr ctrl.Manager) error {
return nil
}

memcachedFn := func(o client.Object) []reconcile.Request {
result := []reconcile.Request{}

// get all Cinder CRs
cinders := &cinderv1beta1.CinderList{}
listOpts := []client.ListOption{
client.InNamespace(o.GetNamespace()),
}
if err := r.Client.List(context.Background(), cinders, listOpts...); err != nil {
Log.Error(err, "Unable to retrieve Cinder CRs %w")
return nil
}

for _, cr := range cinders.Items {
if o.GetName() == cr.Spec.MemcachedInstance {
name := client.ObjectKey{
Namespace: o.GetNamespace(),
Name: cr.Name,
}
Log.Info(fmt.Sprintf("Memcached %s is used by Cinder CR %s", o.GetName(), cr.Name))
result = append(result, reconcile.Request{NamespacedName: name})
}
}
if len(result) > 0 {
return result
}
return nil
}

return ctrl.NewControllerManagedBy(mgr).
For(&cinderv1beta1.Cinder{}).
Owns(&mariadbv1.MariaDBDatabase{}).
Expand All @@ -277,7 +308,8 @@ func (r *CinderReconciler) SetupWithManager(mgr ctrl.Manager) error {
}

func (r *CinderReconciler) reconcileDelete(ctx context.Context, instance *cinderv1beta1.Cinder, helper *helper.Helper) (ctrl.Result, error) {
r.Log.Info(fmt.Sprintf("Reconciling Service '%s' delete", instance.Name))
Log := r.GetLogger(ctx)
Log.Info(fmt.Sprintf("Reconciling Service '%s' delete", instance.Name))

// remove db finalizer first
db, err := mariadbv1.GetDatabaseByName(ctx, helper, instance.Name)
Expand All @@ -296,7 +328,7 @@ func (r *CinderReconciler) reconcileDelete(ctx context.Context, instance *cinder

// Service is deleted so remove the finalizer.
controllerutil.RemoveFinalizer(instance, helper.GetFinalizer())
r.Log.Info(fmt.Sprintf("Reconciled Service '%s' delete successfully", instance.Name))
Log.Info(fmt.Sprintf("Reconciled Service '%s' delete successfully", instance.Name))

return ctrl.Result{}, nil
}
Expand All @@ -308,7 +340,8 @@ func (r *CinderReconciler) reconcileInit(
serviceLabels map[string]string,
serviceAnnotations map[string]string,
) (ctrl.Result, error) {
r.Log.Info(fmt.Sprintf("Reconciling Service '%s' init", instance.Name))
Log := r.GetLogger(ctx)
Log.Info(fmt.Sprintf("Reconciling Service '%s' init", instance.Name))

// Service account, role, binding
rbacRules := []rbacv1.PolicyRule{
Expand Down Expand Up @@ -424,7 +457,7 @@ func (r *CinderReconciler) reconcileInit(
}
if dbSyncjob.HasChanged() {
instance.Status.Hash[cinderv1beta1.DbSyncHash] = dbSyncjob.GetHash()
r.Log.Info(fmt.Sprintf("Service '%s' - Job %s hash added - %s", instance.Name, jobDef.Name, instance.Status.Hash[cinderv1beta1.DbSyncHash]))
Log.Info(fmt.Sprintf("Service '%s' - Job %s hash added - %s", instance.Name, jobDef.Name, instance.Status.Hash[cinderv1beta1.DbSyncHash]))
}
instance.Status.Conditions.MarkTrue(condition.DBSyncReadyCondition, condition.DBSyncReadyMessage)

Expand All @@ -433,12 +466,13 @@ func (r *CinderReconciler) reconcileInit(

// run Cinder db sync - end

r.Log.Info(fmt.Sprintf("Reconciled Service '%s' init successfully", instance.Name))
Log.Info(fmt.Sprintf("Reconciled Service '%s' init successfully", instance.Name))
return ctrl.Result{}, nil
}

func (r *CinderReconciler) reconcileNormal(ctx context.Context, instance *cinderv1beta1.Cinder, helper *helper.Helper) (ctrl.Result, error) {
r.Log.Info(fmt.Sprintf("Reconciling Service '%s'", instance.Name))
Log := r.GetLogger(ctx)
Log.Info(fmt.Sprintf("Reconciling Service '%s'", instance.Name))

serviceLabels := map[string]string{
common.AppSelector: cinder.ServiceName,
Expand All @@ -463,13 +497,13 @@ func (r *CinderReconciler) reconcileNormal(ctx context.Context, instance *cinder
}

if op != controllerutil.OperationResultNone {
r.Log.Info(fmt.Sprintf("TransportURL %s successfully reconciled - operation: %s", transportURL.Name, string(op)))
Log.Info(fmt.Sprintf("TransportURL %s successfully reconciled - operation: %s", transportURL.Name, string(op)))
}

instance.Status.TransportURLSecret = transportURL.Status.SecretName

if instance.Status.TransportURLSecret == "" {
r.Log.Info(fmt.Sprintf("Waiting for TransportURL %s secret to be created", transportURL.Name))
Log.Info(fmt.Sprintf("Waiting for TransportURL %s secret to be created", transportURL.Name))
instance.Status.Conditions.Set(condition.FalseCondition(
condition.RabbitMqTransportURLReadyCondition,
condition.RequestedReason,
Expand Down Expand Up @@ -617,7 +651,7 @@ func (r *CinderReconciler) reconcileNormal(ctx context.Context, instance *cinder
return ctrl.Result{}, err
}
if op != controllerutil.OperationResultNone {
r.Log.Info(fmt.Sprintf("Deployment %s successfully reconciled - operation: %s", instance.Name, string(op)))
Log.Info(fmt.Sprintf("Deployment %s successfully reconciled - operation: %s", instance.Name, string(op)))
}

// Mirror CinderAPI status' APIEndpoints and ReadyCount to this parent CR
Expand All @@ -643,7 +677,7 @@ func (r *CinderReconciler) reconcileNormal(ctx context.Context, instance *cinder
return ctrl.Result{}, err
}
if op != controllerutil.OperationResultNone {
r.Log.Info(fmt.Sprintf("Deployment %s successfully reconciled - operation: %s", instance.Name, string(op)))
Log.Info(fmt.Sprintf("Deployment %s successfully reconciled - operation: %s", instance.Name, string(op)))
}

// Mirror CinderScheduler status' ReadyCount to this parent CR
Expand Down Expand Up @@ -672,7 +706,7 @@ func (r *CinderReconciler) reconcileNormal(ctx context.Context, instance *cinder
return ctrl.Result{}, err
}
if op != controllerutil.OperationResultNone {
r.Log.Info(fmt.Sprintf("Deployment %s successfully reconciled - operation: %s", instance.Name, string(op)))
Log.Info(fmt.Sprintf("Deployment %s successfully reconciled - operation: %s", instance.Name, string(op)))
}

// Mirror CinderBackup status' ReadyCount to this parent CR
Expand Down Expand Up @@ -713,7 +747,7 @@ func (r *CinderReconciler) reconcileNormal(ctx context.Context, instance *cinder
return ctrl.Result{}, err
}
if op != controllerutil.OperationResultNone {
r.Log.Info(fmt.Sprintf("Deployment %s successfully reconciled - operation: %s", instance.Name, string(op)))
Log.Info(fmt.Sprintf("Deployment %s successfully reconciled - operation: %s", instance.Name, string(op)))
}

// Mirror CinderVolume status' ReadyCount to this parent CR
Expand Down Expand Up @@ -748,27 +782,29 @@ func (r *CinderReconciler) reconcileNormal(ctx context.Context, instance *cinder
return ctrl.Result{}, err
}

r.Log.Info(fmt.Sprintf("Reconciled Service '%s' successfully", instance.Name))
Log.Info(fmt.Sprintf("Reconciled Service '%s' successfully", instance.Name))
return ctrl.Result{}, nil
}

func (r *CinderReconciler) reconcileUpdate(ctx context.Context, instance *cinderv1beta1.Cinder, helper *helper.Helper) (ctrl.Result, error) {
r.Log.Info(fmt.Sprintf("Reconciling Service '%s' update", instance.Name))
Log := r.GetLogger(ctx)
Log.Info(fmt.Sprintf("Reconciling Service '%s' update", instance.Name))

// TODO: should have minor update tasks if required
// - delete dbsync hash from status to rerun it?

r.Log.Info(fmt.Sprintf("Reconciled Service '%s' update successfully", instance.Name))
Log.Info(fmt.Sprintf("Reconciled Service '%s' update successfully", instance.Name))
return ctrl.Result{}, nil
}

func (r *CinderReconciler) reconcileUpgrade(ctx context.Context, instance *cinderv1beta1.Cinder, helper *helper.Helper) (ctrl.Result, error) {
r.Log.Info(fmt.Sprintf("Reconciling Service '%s' upgrade", instance.Name))
Log := r.GetLogger(ctx)
Log.Info(fmt.Sprintf("Reconciling Service '%s' upgrade", instance.Name))

// TODO: should have major version upgrade tasks
// -delete dbsync hash from status to rerun it?

r.Log.Info(fmt.Sprintf("Reconciled Service '%s' upgrade successfully", instance.Name))
Log.Info(fmt.Sprintf("Reconciled Service '%s' upgrade successfully", instance.Name))
return ctrl.Result{}, nil
}

Expand Down Expand Up @@ -862,6 +898,9 @@ func (r *CinderReconciler) createHashOfInputHashes(
instance *cinderv1beta1.Cinder,
envVars map[string]env.Setter,
) (string, bool, error) {

Log := r.GetLogger(ctx)

var hashMap map[string]string
changed := false
mergedMapVars := env.MergeEnvs([]corev1.EnvVar{}, envVars)
Expand All @@ -871,7 +910,7 @@ func (r *CinderReconciler) createHashOfInputHashes(
}
if hashMap, changed = util.SetHash(instance.Status.Hash, common.InputHashName, hash); changed {
instance.Status.Hash = hashMap
r.Log.Info(fmt.Sprintf("Input maps hash %s - %s", common.InputHashName, hash))
Log.Info(fmt.Sprintf("Input maps hash %s - %s", common.InputHashName, hash))
}
return hash, changed, nil
}
Expand Down Expand Up @@ -1072,13 +1111,16 @@ func (r *CinderReconciler) volumeDeploymentCreateOrUpdate(ctx context.Context, i
// longer appears in the spec. These will be volumes named something like
// "cinder-volume-X" where "X" is not in the CinderVolumes spec.
func (r *CinderReconciler) volumeCleanupDeployments(ctx context.Context, instance *cinderv1beta1.Cinder) error {

Log := r.GetLogger(ctx)

// Generate a list of volume CRs
volumes := &cinderv1beta1.CinderVolumeList{}
listOpts := []client.ListOption{
client.InNamespace(instance.Namespace),
}
if err := r.Client.List(ctx, volumes, listOpts...); err != nil {
r.Log.Error(err, "Unable to retrieve volume CRs %v")
Log.Error(err, "Unable to retrieve volume CRs %v")
return nil
}

Expand Down
Loading

0 comments on commit 52d9e8d

Please sign in to comment.