Structured logging improvements (#830)

- Made use of native zerolog formatters where possible
- Unified logging fields (camelCase, no spaces)
- Updated logging messages

Signed-off-by: Timofey Ilinykh <ilinytim@gmail.com>

controllers/dnsupdate.go

@@ -91,7 +91,7 @@ func (r *GslbReconciler) gslbDNSEndpoint(gslb *k8gbv1beta1.Gslb) (*externaldns.D
 						log.Info().
 							Str("gslb", gslb.Name).
 							Str("cluster", gslb.Spec.Strategy.PrimaryGeoTag).
-							Str("targets", fmt.Sprintf("%v", finalTargets)).
+							Strs("targets", finalTargets).
 							Str("workload", k8gbv1beta1.Unhealthy.String()).
 							Msg("Executing failover strategy for primary cluster")
 					}
@@ -103,7 +103,7 @@ func (r *GslbReconciler) gslbDNSEndpoint(gslb *k8gbv1beta1.Gslb) (*externaldns.D
 					log.Info().
 						Str("gslb", gslb.Name).
 						Str("cluster", gslb.Spec.Strategy.PrimaryGeoTag).
-						Str("targets", fmt.Sprintf("%v", finalTargets)).
+						Strs("targets", finalTargets).
 						Str("workload", k8gbv1beta1.Healthy.String()).
 						Msg("Executing failover strategy for secondary cluster")
 				}
@@ -117,7 +117,7 @@ func (r *GslbReconciler) gslbDNSEndpoint(gslb *k8gbv1beta1.Gslb) (*externaldns.D
 		r.updateRuntimeStatus(gslb, isPrimary, health, finalTargets)
 		log.Info().
 			Str("gslb", gslb.Name).
-			Str("targets", fmt.Sprintf("%v", finalTargets)).
+			Strs("targets", finalTargets).
 			Msg("Final target list")
 
 		if len(finalTargets) > 0 {

controllers/gslb_controller.go

@@ -25,7 +25,6 @@ import (
 
 	"github.com/k8gb-io/k8gb/controllers/providers/metrics"
 
-	str "github.com/AbsaOSS/gopkg/strings"
 	k8gbv1beta1 "github.com/k8gb-io/k8gb/api/v1beta1"
 	"github.com/k8gb-io/k8gb/controllers/depresolver"
 	"github.com/k8gb-io/k8gb/controllers/internal/utils"
@@ -97,7 +96,7 @@ func (r *GslbReconciler) Reconcile(ctx context.Context, req ctrl.Request) (ctrl.
 	}
 	log.Debug().
 		Str("gslb", gslb.Name).
-		Str("Strategy", str.ToString(gslb.Spec.Strategy)).
+		Interface("strategy", gslb.Spec.Strategy).
 		Msg("Resolved strategy")
 	// == Finalizer business ==
 
@@ -265,20 +264,23 @@ func (r *GslbReconciler) SetupWithManager(mgr ctrl.Manager) error {
 			},
 		}
 
-		strToInt := func(str string) int {
-			intValue, err := strconv.Atoi(str)
+		annotationToInt := func(k string, v string) int {
+			intValue, err := strconv.Atoi(v)
 			if err != nil {
-				log.Err(err).Msg("can't convert string to int")
+				log.Err(err).
+					Str("annotationKey", k).
+					Str("annotationValue", v).
+					Msg("Can't parse annotation value to int")
 			}
 			return intValue
 		}
 
 		for annotationKey, annotationValue := range a.GetAnnotations() {
 			switch annotationKey {
 			case dnsTTLSecondsAnnotation:
-				gslb.Spec.Strategy.DNSTtlSeconds = strToInt(annotationValue)
+				gslb.Spec.Strategy.DNSTtlSeconds = annotationToInt(annotationKey, annotationValue)
 			case splitBrainThresholdSecondsAnnotation:
-				gslb.Spec.Strategy.SplitBrainThresholdSeconds = strToInt(annotationValue)
+				gslb.Spec.Strategy.SplitBrainThresholdSeconds = annotationToInt(annotationKey, annotationValue)
 			}
 		}
 
@@ -300,7 +302,7 @@ func (r *GslbReconciler) SetupWithManager(mgr ctrl.Manager) error {
 		err = controllerutil.SetControllerReference(ingressToReuse, gslb, r.Scheme)
 		if err != nil {
 			log.Err(err).
-				Str("Ingress", ingressToReuse.Name).
+				Str("ingress", ingressToReuse.Name).
 				Str("gslb", gslb.Name).
 				Msg("Cannot set the Ingress as the owner of the Gslb")
 		}

controllers/logging/log.go

@@ -67,9 +67,9 @@ func (l *loggerFactory) get() zerolog.Logger {
 			Logger()
 	}
 	logger.Info().Msg("Logger configured")
-	logger.Debug().
-		Str("Format", l.log.Format.String()).
-		Str("Level", l.log.Level.String()).
+	logger.Info().
+		Str("format", l.log.Format.String()).
+		Str("level", l.log.Level.String()).
 		Msg("Logger settings")
 	return logger
 }

controllers/providers/assistant/gslb.go

@@ -29,7 +29,6 @@ import (
 	"github.com/k8gb-io/k8gb/controllers/internal/utils"
 	"github.com/k8gb-io/k8gb/controllers/logging"
 
-	str "github.com/AbsaOSS/gopkg/strings"
 	"github.com/miekg/dns"
 	corev1 "k8s.io/api/core/v1"
 	v1beta1 "k8s.io/api/networking/v1beta1"
@@ -65,7 +64,7 @@ func (r *Gslb) CoreDNSExposedIPs() ([]string, error) {
 	serviceList := &corev1.ServiceList{}
 	sel, err := labels.Parse(coreDNSServiceLabel)
 	if err != nil {
-		log.Error().Err(err).Msg("Badly formed label selector")
+		log.Err(err).Msg("Badly formed label selector")
 		return nil, err
 	}
 	listOption := &client.ListOptions{
@@ -83,7 +82,7 @@ func (r *Gslb) CoreDNSExposedIPs() ([]string, error) {
 		log.Warn().Msg("More than 1 CoreDNS service was found")
 		for _, service := range serviceList.Items {
 			log.Info().
-				Str("ServiceName", service.Name).
+				Str("serviceName", service.Name).
 				Msg("Found CoreDNS service")
 		}
 		err := coreerrors.New("more than 1 CoreDNS service was found. Check if CoreDNS exposed correctly")
@@ -97,15 +96,15 @@ func (r *Gslb) CoreDNSExposedIPs() ([]string, error) {
 	} else {
 		errMessage := "no LoadBalancer ExternalIPs are found"
 		log.Warn().
-			Str("ServiceName", coreDNSService.Name).
+			Str("serviceName", coreDNSService.Name).
 			Msg(errMessage)
 		err := coreerrors.New(errMessage)
 		return nil, err
 	}
 	IPs, err := utils.Dig(lbHostname, r.edgeDNSServers...)
 	if err != nil {
 		log.Warn().Err(err).
-			Str("LoadBalancerHostname", lbHostname).
+			Str("loadBalancerHostname", lbHostname).
 			Msg("Can't dig CoreDNS service LoadBalancer FQDN")
 		return nil, err
 	}
@@ -160,7 +159,9 @@ func (r *Gslb) SaveDNSEndpoint(namespace string, i *externaldns.DNSEndpoint) err
 	if err != nil && errors.IsNotFound(err) {
 
 		// Create the DNSEndpoint
-		log.Info().Msgf("Creating a new DNSEndpoint:\n %s", str.ToString(i))
+		log.Info().
+			Interface("DNSEndpoint", i).
+			Msgf("Creating a new DNSEndpoint")
 		err = r.client.Create(context.TODO(), i)
 
 		if err != nil {
@@ -227,7 +228,7 @@ func (r *Gslb) InspectTXTThreshold(fqdn string, splitBrainThreshold time.Duratio
 	txt, err := utils.Exchange(m, r.edgeDNSServers)
 	if err != nil {
 		log.Info().
-			Str("edgeDNSServers", r.edgeDNSServers.String()).
+			Interface("edgeDNSServers", r.edgeDNSServers).
 			Err(err).
 			Msg("Contacting EdgeDNS server for TXT split brain record")
 		return err
@@ -239,17 +240,17 @@ func (r *Gslb) InspectTXTThreshold(fqdn string, splitBrainThreshold time.Duratio
 			timeFromTXT, err := time.Parse("2006-01-02T15:04:05", timestamp)
 			if err != nil {
 				log.Err(err).
-					Str("raw record", t.String()).
-					Str("raw timestamp", timestamp).
+					Str("rawRecord", t.String()).
+					Str("rawTimestamp", timestamp).
 					Msg("Split brain TXT: can't parse timestamp")
 				return err
 			}
 			now := time.Now().UTC()
 			diff := now.Sub(timeFromTXT)
 			log.Debug().
-				Str("raw record", t.String()).
-				Str("raw timestamp", timestamp).
-				Str("parsed", timeFromTXT.String()).
+				Str("rawRecord", t.String()).
+				Str("rawTimestamp", timestamp).
+				Time("parsed", timeFromTXT).
 				Str("diff", diff.String()).
 				Msg("Split brain TXT")
 
@@ -279,9 +280,9 @@ func dnsQuery(host string, nameservers utils.DNSList) (*dns.Msg, error) {
 	if err != nil {
 		log.Warn().
 			Str("fqdn", fqdn).
-			Str("nameservers", nameservers.String()).
+			Interface("nameservers", nameservers).
 			Err(err).
-			Msg("Can't resolve FQDN using nameservers")
+			Msg("can't resolve FQDN using nameservers")
 	}
 	return dnsMsgA, err
 }
@@ -299,8 +300,8 @@ func (r *Gslb) GetExternalTargets(host string, extClusterNsNames map[string]stri
 		}
 		log.Info().
 			Str("nameserver", cluster).
-			Str("edgeDNS", r.edgeDNSServers.String()).
-			Str("glue A record", fmt.Sprintf("%v", glueA.Answer)).
+			Interface("edgeDNSServers", r.edgeDNSServers).
+			Interface("glueARecord", glueA.Answer).
 			Msg("Resolved glue A record for NS")
 		glueARecords := getARecords(glueA)
 		var hostToUse string
@@ -319,7 +320,7 @@ func (r *Gslb) GetExternalTargets(host string, extClusterNsNames map[string]stri
 		if len(clusterTargets) > 0 {
 			targets = append(targets, clusterTargets...)
 			log.Info().
-				Str("cluster targets", fmt.Sprintf("%s", clusterTargets)).
+				Strs("clusterTargets", clusterTargets).
 				Str("cluster", cluster).
 				Msg("Extend Gslb targets by targets from cluster")
 		}

controllers/providers/dns/external.go

@@ -54,7 +54,7 @@ func NewExternalDNS(config depresolver.Config, assistant assistant2.Assistant) *
 func (p *ExternalDNSProvider) CreateZoneDelegationForExternalDNS(gslb *k8gbv1beta1.Gslb) error {
 	ttl := externaldns.TTL(gslb.Spec.Strategy.DNSTtlSeconds)
 	log.Info().
-		Str("provider", p.String()).
+		Interface("provider", p).
 		Msg("Creating/Updating DNSEndpoint CRDs")
 	NSServerList := []string{p.config.GetClusterNSName()}
 	for _, v := range p.config.GetExternalClusterNSNames() {

controllers/providers/dns/infoblox.go

@@ -115,11 +115,11 @@ func (p *InfobloxProvider) CreateZoneDelegationForExternalDNS(gslb *k8gbv1beta1.
 
 			if !reflect.DeepEqual(findZone.DelegateTo, currentList) {
 				log.Info().
-					Str("records", fmt.Sprintf("(%v)", findZone.DelegateTo)).
+					Interface("records", findZone.DelegateTo).
 					Msg("Found delegated zone records")
 				log.Info().
-					Str("DNS zone", p.config.DNSZone).
-					Str("server list", fmt.Sprintf("%v", currentList)).
+					Str("DNSZone", p.config.DNSZone).
+					Interface("serverList", currentList).
 					Msg("Updating delegated zone with the server list")
 				_, err = p.updateZoneDelegated(objMgr, findZone.Ref, currentList)
 				if err != nil {
@@ -131,11 +131,11 @@ func (p *InfobloxProvider) CreateZoneDelegationForExternalDNS(gslb *k8gbv1beta1.
 		}
 	} else {
 		log.Info().
-			Str("DNS zone", p.config.DNSZone).
+			Str("DNSZone", p.config.DNSZone).
 			Msg("Creating delegated zone")
 		sortZones(delegateTo)
 		log.Debug().
-			Str("records", fmt.Sprintf("%v", delegateTo)).
+			Interface("records", delegateTo).
 			Msg("Delegated records")
 		_, err = p.createZoneDelegated(objMgr, p.config.DNSZone, delegateTo)
 		if err != nil {
@@ -167,7 +167,7 @@ func (p *InfobloxProvider) Finalize(gslb *k8gbv1beta1.Gslb) error {
 		}
 		if len(findZone.Ref) > 0 {
 			log.Info().
-				Str("DNS zone", p.config.DNSZone).
+				Str("DNSZone", p.config.DNSZone).
 				Msg("Deleting delegated zone")
 			_, err := p.deleteZoneDelegated(objMgr, findZone.Ref)
 			if err != nil {
@@ -185,7 +185,7 @@ func (p *InfobloxProvider) Finalize(gslb *k8gbv1beta1.Gslb) error {
 	if findTXT != nil {
 		if len(findTXT.Ref) > 0 {
 			log.Info().
-				Str("TXT records", heartbeatTXTName).
+				Str("TXTRecords", heartbeatTXTName).
 				Msg("Deleting split brain TXT record")
 			_, err := p.deleteTXTRecord(objMgr, findTXT.Ref)
 			if err != nil {

main.go

@@ -21,8 +21,6 @@ Generated by GoLic, for more details see: https://github.com/AbsaOSS/golic
 import (
 	"os"
 
-	str "github.com/AbsaOSS/gopkg/strings"
-
 	k8gbv1beta1 "github.com/k8gb-io/k8gb/api/v1beta1"
 	"github.com/k8gb-io/k8gb/controllers"
 	"github.com/k8gb-io/k8gb/controllers/depresolver"
@@ -70,13 +68,13 @@ func run() error {
 	log.Info().
 		Str("version", version).
 		Str("commit", commit).
-		Msg("K8gb status")
+		Msg("k8gb info")
 	if err != nil {
-		log.Err(err).Msg("can't resolve environment variables")
+		log.Err(err).Msg("Can't resolve environment variables")
 		return err
 	}
 	log.Debug().
-		Str("config", str.ToString(config)).
+		Interface("config", config).
 		Msg("Resolved config")
 
 	ctrl.SetLogger(logging.NewLogrAdapter(log))
@@ -89,7 +87,7 @@ func run() error {
 		LeaderElectionID:   "8020e9ff.absa.oss",
 	})
 	if err != nil {
-		log.Err(err).Msg("Unable to start k8gb")
+		log.Err(err).Msg("Unable to create k8gb operator manager")
 		return err
 	}
 
@@ -104,7 +102,7 @@ func run() error {
 	schemeBuilder := &scheme.Builder{GroupVersion: schema.GroupVersion{Group: "externaldns.k8s.io", Version: "v1alpha1"}}
 	schemeBuilder.Register(&externaldns.DNSEndpoint{}, &externaldns.DNSEndpointList{})
 	if err := schemeBuilder.AddToScheme(mgr.GetScheme()); err != nil {
-		log.Err(err).Msg("Extending scheme")
+		log.Err(err).Msg("Unable to register ExternalDNS resource schemas")
 		return err
 	}
 
@@ -120,30 +118,32 @@ func run() error {
 	defer metrics.Metrics().Unregister()
 	err = metrics.Metrics().Register()
 	if err != nil {
-		log.Err(err).Msg("Register metrics error")
+		log.Err(err).Msg("Unable to register metrics")
 		return err
 	}
 
 	log.Info().Msg("Resolving DNS provider")
 	f, err = dns.NewDNSProviderFactory(reconciler.Client, *reconciler.Config)
 	if err != nil {
-		log.Err(err).Msg("Unable to create factory")
+		log.Err(err).Msg("Unable to create DNS provider factory")
 		return err
 	}
 	reconciler.DNSProvider = f.Provider()
-	log.Info().Str("provider", reconciler.DNSProvider.String()).Msg("Started")
+	log.Info().
+		Str("provider", reconciler.DNSProvider.String()).
+		Msg("Started DNS provider")
 
 	if err = reconciler.SetupWithManager(mgr); err != nil {
-		log.Err(err).Msg("Unable to create controller Gslb")
+		log.Err(err).Msg("Unable to create Gslb controller")
 		return err
 	}
 	metrics.Metrics().SetRuntimeInfo(version, commit)
 	// +kubebuilder:scaffold:builder
 	log.Info().Msg("Starting k8gb")
 	if err := mgr.Start(ctrl.SetupSignalHandler()); err != nil {
-		log.Err(err).Msg("Problem running k8gb controller")
+		log.Err(err).Msg("Problem running k8gb")
 		return err
 	}
-	log.Info().Msg("Gracefully finished, bye!\n")
+	log.Info().Msg("Gracefully finished, bye!")
 	return nil
 }